From 0177ed2d5fe1dba981e07b426f5b4d4bc05bc279 Mon Sep 17 00:00:00 2001 From: Paddy Carver Date: Wed, 7 Jul 2021 05:57:06 -0700 Subject: [PATCH] Add terraform-plugin-log support. Set up loggers using terraform-plugin-log v0.1.0, and update our tfprotov5 and tfprotov6 server packages to have trace and error logs, and to inject useful values in requests opportunistically. --- .changelog/93.txt | 11 ++ go.mod | 4 +- go.sum | 25 +++-- tfprotov5/server/plugin.go | 4 +- tfprotov5/server/server.go | 213 +++++++++++++++++++++++++++++++++++- tfprotov6/server/plugin.go | 4 +- tfprotov6/server/server.go | 214 ++++++++++++++++++++++++++++++++++++- 7 files changed, 456 insertions(+), 19 deletions(-) create mode 100644 .changelog/93.txt diff --git a/.changelog/93.txt b/.changelog/93.txt new file mode 100644 index 00000000..a9ce87c7 --- /dev/null +++ b/.changelog/93.txt @@ -0,0 +1,11 @@ +```release-note:feature +Added support for [terraform-plugin-log](https://github.com/hashicorp/terraform-plugin-log) v0.1.0, injecting loggers for SDKs and the provider into requests and adding trace and error log lines to request handlers. +``` + +```release-note:breaking-change +`tf6server.New` and `tf5server.New` now accept a name argument (meant to be the full registry path of the provider, e.g. registry.terraform.io/hashicorp/random) and a variadic argument of `ServeOpts`, just like the `Serve` function. Providers calling `Serve` will not notice any change. Providers calling `New` directly should pass the name and any options they would like the server to be configured with. +``` + +```release-note:enhancement +New `WithoutLogStderrOverride` and `WithoutLogLocation` `ServeOpt` helper functions have been added to `tf6server` and `tf5server`. These helpers can be passed to `Serve` or `New` to disable default logging behaviors for SDK and provider logs. `WithoutLogStderrOverride` disables using the stderr that existed at startup instead of the one that exists when the log function is called; it is recommended to not use this unless you understand the impacts, as Terraform's default behavior is counter-intuitive. `WithoutLogLocation` excludes filename and line numbers from log output. +``` diff --git a/go.mod b/go.mod index 8dd0621a..f4298131 100644 --- a/go.mod +++ b/go.mod @@ -5,8 +5,10 @@ go 1.15 require ( github.com/golang/protobuf v1.4.2 github.com/google/go-cmp v0.5.2 - github.com/hashicorp/go-hclog v0.0.0-20180709165350-ff2cf002a8dd + github.com/hashicorp/go-hclog v0.16.1 github.com/hashicorp/go-plugin v1.3.0 + github.com/hashicorp/go-uuid v1.0.2 + github.com/hashicorp/terraform-plugin-log v0.1.0 github.com/kr/pretty v0.1.0 // indirect github.com/nsf/jsondiff v0.0.0-20200515183724-f29ed568f4ce github.com/vmihailenco/msgpack v4.0.4+incompatible diff --git a/go.sum b/go.sum index 76609145..e9761eea 100644 --- a/go.sum +++ b/go.sum @@ -3,12 +3,15 @@ github.com/BurntSushi/toml v0.3.1/go.mod h1:xHWCNGjB5oqiDr8zfno3MHue2Ht5sIBksp03 github.com/census-instrumentation/opencensus-proto v0.2.1/go.mod h1:f6KPmirojxKA12rnyqOA5BBL4O983OfeGPqjHWSTneU= github.com/client9/misspell v0.3.4/go.mod h1:qj6jICC3Q7zFZvVWo7KLAzC3yx5G7kyvSDkc90ppPyw= github.com/cncf/udpa/go v0.0.0-20191209042840-269d4d468f6f/go.mod h1:M8M6+tZqaGXZJjfX53e64911xZQV5JYwmTeXPW+k8Sc= -github.com/davecgh/go-spew v1.1.0 h1:ZDRjVQ15GmhC3fiQ8ni8+OwkZQO4DARzQgrnXU1Liz8= github.com/davecgh/go-spew v1.1.0/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= +github.com/davecgh/go-spew v1.1.1 h1:vj9j/u1bqnvCEfJOwUhtlOARqs3+rkHYY13jYWTU97c= +github.com/davecgh/go-spew v1.1.1/go.mod h1:J7Y8YcW2NihsgmVo/mv3lAwl/skON4iLHjSsI+c5H38= github.com/envoyproxy/go-control-plane v0.9.0/go.mod h1:YTl/9mNaCwkRvm6d1a2C3ymFceY/DCBVvsKhRF0iEA4= github.com/envoyproxy/go-control-plane v0.9.1-0.20191026205805-5f8ba28d4473/go.mod h1:YTl/9mNaCwkRvm6d1a2C3ymFceY/DCBVvsKhRF0iEA4= github.com/envoyproxy/go-control-plane v0.9.4/go.mod h1:6rpuAdCZL397s3pYoYcLgu1mIlRU8Am5FuJP05cCM98= github.com/envoyproxy/protoc-gen-validate v0.1.0/go.mod h1:iSmxcyjqTsJpI2R4NaDN7+kN2VEUnK/pcBlmesArF7c= +github.com/fatih/color v1.7.0 h1:DkWD4oS2D8LGGgTQ6IvwJJXSL5Vp2ffcQg58nFV38Ys= +github.com/fatih/color v1.7.0/go.mod h1:Zm6kSWBoL9eyXnKyktHP6abPY2pDugNf5KwzbycvMj4= github.com/golang/glog v0.0.0-20160126235308-23def4e6c14b/go.mod h1:SBH7ygxi8pfUlaOkMMuAQtPIUF8ecWP5IEl/CR7VP2Q= github.com/golang/mock v1.1.1/go.mod h1:oTYuIxOrZwtPieC+H1uAHpcLFnEyAGVDL/k47Jfbm0A= github.com/golang/protobuf v1.2.0/go.mod h1:6lQm79b+lXiMfvg/cZm0SGofjICqVBUtrP5yJMmIC1U= @@ -26,14 +29,18 @@ github.com/golang/protobuf v1.4.2/go.mod h1:oDoupMAO8OvCJWAcko0GGGIgR6R6ocIYbsSw github.com/google/go-cmp v0.2.0/go.mod h1:oXzfMopK8JAjlY9xF4vHSVASa0yLyX7SntLO5aqRK0M= github.com/google/go-cmp v0.3.0/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMywk6iLU= github.com/google/go-cmp v0.3.1/go.mod h1:8QqcDgzrUqlUb/G2PQTWiueGozuR1884gddMywk6iLU= -github.com/google/go-cmp v0.4.0 h1:xsAVV57WRhGj6kEIi8ReJzQlHHqcBYCElAvkovg3B/4= github.com/google/go-cmp v0.4.0/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= github.com/google/go-cmp v0.5.2 h1:X2ev0eStA3AbceY54o37/0PQ/UWqKEiiO2dKL5OPaFM= github.com/google/go-cmp v0.5.2/go.mod h1:v8dTdLbMG2kIc/vJvl+f65V22dbkXbowE6jgT/gNBxE= -github.com/hashicorp/go-hclog v0.0.0-20180709165350-ff2cf002a8dd h1:rNuUHR+CvK1IS89MMtcF0EpcVMZtjKfPRp4MEmt/aTs= github.com/hashicorp/go-hclog v0.0.0-20180709165350-ff2cf002a8dd/go.mod h1:9bjs9uLqI8l75knNv3lV1kA55veR+WUPSiKIWcQHudI= +github.com/hashicorp/go-hclog v0.16.1 h1:IVQwpTGNRRIHafnTs2dQLIk4ENtneRIEEJWOVDqz99o= +github.com/hashicorp/go-hclog v0.16.1/go.mod h1:whpDNt7SSdeAju8AWKIWsul05p54N/39EeqMAyrmvFQ= github.com/hashicorp/go-plugin v1.3.0 h1:4d/wJojzvHV1I4i/rrjVaeuyxWrLzDE1mDCyDy8fXS8= github.com/hashicorp/go-plugin v1.3.0/go.mod h1:F9eH4LrE/ZsRdbwhfjs9k9HoDUwAHnYtXdgmf1AVNs0= +github.com/hashicorp/go-uuid v1.0.2 h1:cfejS+Tpcp13yd5nYHWDI6qVCny6wyX2Mt5SGur2IGE= +github.com/hashicorp/go-uuid v1.0.2/go.mod h1:6SBZvOh/SIDV7/2o3Jml5SYk/TvGqwFJ/bN7x4byOro= +github.com/hashicorp/terraform-plugin-log v0.1.0 h1:Y3WhhGY0ETvfHlCM0ad7BG1lzTNEblcmh6PrFw/4o9g= +github.com/hashicorp/terraform-plugin-log v0.1.0/go.mod h1:qRu7tRIL3c89jRYT7UBkSJ+DJ8NPPjQGawQgrGms47s= github.com/hashicorp/yamux v0.0.0-20180604194846-3520598351bb h1:b5rjCoWHc7eqmAS4/qyk21ZsHyb6Mxv/jykxvNTkU4M= github.com/hashicorp/yamux v0.0.0-20180604194846-3520598351bb/go.mod h1:+NfK9FKeTrX5uv1uIXGdwYDTeHna2qgaIlx54MXqjAM= github.com/jhump/protoreflect v1.6.0 h1:h5jfMVslIg6l29nsMs0D8Wj17RDVdNYti0vDN/PZZoE= @@ -43,6 +50,11 @@ github.com/kr/pretty v0.1.0/go.mod h1:dAy3ld7l9f0ibDNOQOHHMYYIIbhfbHSm3C4ZsoJORN github.com/kr/pty v1.1.1/go.mod h1:pFQYn66WHrOpPYNljwOMqo10TkYh1fy3cYio2l3bCsQ= github.com/kr/text v0.1.0 h1:45sCR5RtlFHMR4UwH9sdQ5TC8v0qDQCHnXt+kaKSTVE= github.com/kr/text v0.1.0/go.mod h1:4Jbv+DJW3UT/LiOwJeYQe1efqtUx/iVham/4vfdArNI= +github.com/mattn/go-colorable v0.1.4 h1:snbPLB8fVfU9iwbbo30TPtbLRzwWu6aJS6Xh4eaaviA= +github.com/mattn/go-colorable v0.1.4/go.mod h1:U0ppj6V5qS13XJ6of8GYAs25YV2eR4EVcfRqFIhoBtE= +github.com/mattn/go-isatty v0.0.8/go.mod h1:Iq45c/XA43vh69/j3iqttzPXn0bhXyGjM0Hdxcsrc5s= +github.com/mattn/go-isatty v0.0.10 h1:qxFzApOv4WsAL965uUPIsXzAKCZxN2p9UqdhFS4ZW10= +github.com/mattn/go-isatty v0.0.10/go.mod h1:qgIWMr58cqv1PHHyhnkY9lrL7etaEgOFcMEpPG5Rm84= github.com/mitchellh/go-testing-interface v0.0.0-20171004221916-a61a99592b77 h1:7GoSOOW2jpsfkntVKaS2rAr1TJqfcxotyaUcuxoZSzg= github.com/mitchellh/go-testing-interface v0.0.0-20171004221916-a61a99592b77/go.mod h1:kRemZodwjscx+RGhAo8eIhFbs2+BFgRtFPeD/KE+zxI= github.com/nsf/jsondiff v0.0.0-20200515183724-f29ed568f4ce h1:RPclfga2SEJmgMmz2k+Mg7cowZ8yv4Trqw9UsJby758= @@ -53,6 +65,7 @@ github.com/pmezard/go-difflib v1.0.0 h1:4DBwDE0NGyQoBHbLQYPwSUPoCMWR5BEzIk/f1lZb github.com/pmezard/go-difflib v1.0.0/go.mod h1:iKH77koFhYxTK1pcRnkKkqfTogsbg7gZNVY4sRDYZ/4= github.com/prometheus/client_model v0.0.0-20190812154241-14fe0d1b01d4/go.mod h1:xMI15A0UPsDsEKsMN9yxemIoYk6Tm2C1GtYGdfGttqA= github.com/stretchr/objx v0.1.0/go.mod h1:HFkY916IF+rwdDfMAkV7OtwuqBVzrE8GR6GFx+wExME= +github.com/stretchr/testify v1.2.2/go.mod h1:a8OnRcib4nhh0OaRAV+Yts87kKdq0PP7pXfy6kDkUVs= github.com/stretchr/testify v1.3.0 h1:TivCn/peBQ7UY8ooIcPgZFpTNSz0Q2U6UrFlUfqbe0Q= github.com/stretchr/testify v1.3.0/go.mod h1:M5WIy9Dh21IEIfnGCwXGc5bZfKNJtfHm1UVUgZn+9EI= github.com/vmihailenco/msgpack v4.0.4+incompatible h1:dSLoQfGFAo3F6OoNhwUmLwVgaUXK79GlxNBwueZn0xI= @@ -66,7 +79,6 @@ golang.org/x/net v0.0.0-20180530234432-1e491301e022/go.mod h1:mL1N/T3taQHkDXs73r golang.org/x/net v0.0.0-20180724234803-3673e40ba225/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= golang.org/x/net v0.0.0-20180826012351-8a410e7b638d/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= golang.org/x/net v0.0.0-20190213061140-3a22650c66bd/go.mod h1:mL1N/T3taQHkDXs73rZJwtUhF3w3ftmwwsq0BUmARs4= -golang.org/x/net v0.0.0-20190311183353-d8887717615a h1:oWX7TPOiFAMXLq8o0ikBYfCJVlRHBcsciT5bXOrH628= golang.org/x/net v0.0.0-20190311183353-d8887717615a/go.mod h1:t9HGtf8HONx5eT2rtn7q6eTqICYqUVnKs3thJo3Qplg= golang.org/x/net v0.0.0-20190603091049-60506f45cf65/go.mod h1:HSz+uSET+XFnRR8LxR5pz3Of3rY3CfYBVs4xY44aLks= golang.org/x/net v0.0.0-20200301022130-244492dfa37a h1:GuSPYbZzB5/dcLNCwLQLsg3obCJtX9IJhpXkvY7kzk0= @@ -76,9 +88,10 @@ golang.org/x/sync v0.0.0-20180314180146-1d60e4601c6f/go.mod h1:RxMgew5VJxzue5/jJ golang.org/x/sync v0.0.0-20181108010431-42b317875d0f/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sync v0.0.0-20190423024810-112230192c58/go.mod h1:RxMgew5VJxzue5/jJTE5uejpjVlOe/izrB70Jof72aM= golang.org/x/sys v0.0.0-20180830151530-49385e6e1522/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= -golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a h1:1BGLXjeY4akVXGgbC9HugT3Jv3hCI0z56oJR5vAMgBU= golang.org/x/sys v0.0.0-20190215142949-d0b11bdaac8a/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= -golang.org/x/text v0.3.0 h1:g61tztE5qeGQ89tm6NTjjM9VPIm088od1l6aSorWRWg= +golang.org/x/sys v0.0.0-20190222072716-a9d3bda3a223/go.mod h1:STP8DvDyc/dI5b8T5hshtkjS+E42TnysNCUPdjciGhY= +golang.org/x/sys v0.0.0-20191008105621-543471e840be h1:QAcqgptGM8IQBC9K/RC4o+O9YmqEm0diQn9QmZw/0mU= +golang.org/x/sys v0.0.0-20191008105621-543471e840be/go.mod h1:h1NjWce9XRLGQEsW7wpKNCjG9DtNlClVuFLEZdDNbEs= golang.org/x/text v0.3.0/go.mod h1:NqM8EUOU14njkJ3fqMW+pc6Ldnwhi/IjpwHt7yyuwOQ= golang.org/x/text v0.3.2 h1:tW2bmiBqwgJj/UpqtC8EpXEZVYOwU0yG4iWbprSVAcs= golang.org/x/text v0.3.2/go.mod h1:bEr9sfX3Q8Zfm5fL9x+3itogRgK3+ptLWKqgva+5dAk= diff --git a/tfprotov5/server/plugin.go b/tfprotov5/server/plugin.go index efa32947..a378985d 100644 --- a/tfprotov5/server/plugin.go +++ b/tfprotov5/server/plugin.go @@ -17,6 +17,8 @@ import ( // serve tfprotov5.ProviderServers as gRPC plugins for go-plugin. type GRPCProviderPlugin struct { GRPCProvider func() tfprotov5.ProviderServer + opts []ServeOpt + name string } // Server always returns an error; we're only implementing the GRPCPlugin @@ -40,6 +42,6 @@ func (p *GRPCProviderPlugin) GRPCClient(context.Context, *plugin.GRPCBroker, *gr // GRPCServer registers the gRPC provider server with the gRPC server that // go-plugin is standing up. func (p *GRPCProviderPlugin) GRPCServer(broker *plugin.GRPCBroker, s *grpc.Server) error { - tfplugin5.RegisterProviderServer(s, New(p.GRPCProvider())) + tfplugin5.RegisterProviderServer(s, New(p.name, p.GRPCProvider(), p.opts...)) return nil } diff --git a/tfprotov5/server/server.go b/tfprotov5/server/server.go index 34da72a4..00dd6c53 100644 --- a/tfprotov5/server/server.go +++ b/tfprotov5/server/server.go @@ -4,14 +4,20 @@ import ( "context" "sync" - "github.com/hashicorp/go-hclog" - "github.com/hashicorp/go-plugin" "github.com/hashicorp/terraform-plugin-go/tfprotov5" "github.com/hashicorp/terraform-plugin-go/tfprotov5/internal/fromproto" "github.com/hashicorp/terraform-plugin-go/tfprotov5/internal/tfplugin5" "github.com/hashicorp/terraform-plugin-go/tfprotov5/internal/toproto" + + "github.com/hashicorp/go-hclog" + "github.com/hashicorp/go-plugin" + "github.com/hashicorp/go-uuid" + tflog "github.com/hashicorp/terraform-plugin-log" + tfsdklog "github.com/hashicorp/terraform-plugin-log/sdk" ) +const tflogSubsystemName = "proto" + // ServeOpt is an interface for defining options that can be passed to the // Serve function. Each implementation modifies the ServeConfig being // generated. A slice of ServeOpts then, cumulatively applied, render a full @@ -27,6 +33,9 @@ type ServeConfig struct { debugCtx context.Context debugCh chan *plugin.ReattachConfig debugCloseCh chan struct{} + + disableLogInitStderr bool + disableLogLocation bool } type serveConfigFunc func(*ServeConfig) error @@ -55,6 +64,26 @@ func WithGoPluginLogger(logger hclog.Logger) ServeOpt { }) } +// WithoutLogStderrOverride returns a ServeOpt that will disable the +// terraform-plugin-log behavior of logging to the stderr that existed at +// startup, not the stderr that exists when the logging statement is called. +func WithoutLogStderrOverride() ServeOpt { + return serveConfigFunc(func(in *ServeConfig) error { + in.disableLogInitStderr = true + return nil + }) +} + +// WithoutLogLocation returns a ServeOpt that will exclude file names and line +// numbers from log output for the terraform-plugin-log logs generated by the +// SDKs and provider. +func WithoutLogLocation() ServeOpt { + return serveConfigFunc(func(in *ServeConfig) error { + in.disableLogLocation = true + return nil + }) +} + // Serve starts a tfprotov5.ProviderServer serving, ready for Terraform to // connect to it. The name passed in should be the fully qualified name that // users will enter in the source field of the required_providers block, like @@ -105,6 +134,10 @@ type server struct { stopMu sync.Mutex stopCh chan struct{} + + tflogSDKOpts []tfsdklog.Option + tflogOpts []tflog.Option + name string } func mergeStop(ctx context.Context, cancel context.CancelFunc, stopCh chan struct{}) { @@ -130,61 +163,157 @@ func (s *server) stoppableContext(ctx context.Context) context.Context { return stoppable } +// loggingContext returns a context that wraps `ctx` and has +// terraform-plugin-log loggers injected. +func (s *server) loggingContext(ctx context.Context) context.Context { + // generate a request ID + reqID, err := uuid.GenerateUUID() + if err != nil { + reqID = "unable to assign request ID: " + err.Error() + } + + // set up the logger SDK loggers are derived from + ctx = tfsdklog.New(ctx, append([]tfsdklog.Option{ + tfsdklog.WithLevelFromEnv("TF", "LOG", "SDK"), + }, s.tflogSDKOpts...)...) + ctx = tfsdklog.With(ctx, "tf_req_id", reqID) + ctx = tfsdklog.With(ctx, "tf_provider_addr", s.name) + + // set up our protocol-level subsystem logger + ctx = tfsdklog.NewSubsystem(ctx, tflogSubsystemName, append([]tfsdklog.Option{ + tfsdklog.WithLevelFromEnv("TF", "LOG", "SDK", "PROTO"), + }, s.tflogSDKOpts...)...) + + // set up the provider logger + ctx = tflog.New(ctx, s.tflogOpts...) + ctx = tflog.With(ctx, "tf_req_id", reqID) + ctx = tflog.With(ctx, "tf_provider_addr", s.name) + return ctx +} + +func rpcLoggingContext(ctx context.Context, rpc string) context.Context { + ctx = tfsdklog.With(ctx, "tf_rpc", rpc) + ctx = tfsdklog.SubsystemWith(ctx, tflogSubsystemName, "tf_rpc", rpc) + ctx = tflog.With(ctx, "tf_rpc", rpc) + return ctx +} + +func resourceLoggingContext(ctx context.Context, resource string) context.Context { + ctx = tfsdklog.With(ctx, "tf_resource_type", resource) + ctx = tfsdklog.SubsystemWith(ctx, tflogSubsystemName, "tf_resource_type", resource) + ctx = tflog.With(ctx, "tf_resource_type", resource) + return ctx +} + +func dataSourceLoggingContext(ctx context.Context, dataSource string) context.Context { + ctx = tfsdklog.With(ctx, "tf_data_source_type", dataSource) + ctx = tfsdklog.SubsystemWith(ctx, tflogSubsystemName, "tf_data_source_type", dataSource) + ctx = tflog.With(ctx, "tf_data_source_type", dataSource) + return ctx +} + // New converts a tfprotov5.ProviderServer into a server capable of handling // Terraform protocol requests and issuing responses using the gRPC types. -func New(serve tfprotov5.ProviderServer) tfplugin5.ProviderServer { +func New(name string, serve tfprotov5.ProviderServer, opts ...ServeOpt) tfplugin5.ProviderServer { + var conf ServeConfig + for _, opt := range opts { + err := opt.ApplyServeOpt(&conf) + if err != nil { + // this should never happen, we already executed all + // this code as part of Serve + panic(err) + } + } + var sdkOptions []tfsdklog.Option + var options []tflog.Option + sdkOptions = append(sdkOptions, tfsdklog.WithLevelFromEnv("TF", "LOG", "SDK", "PROTO")) + if !conf.disableLogInitStderr { + sdkOptions = append(sdkOptions, tfsdklog.WithStderrFromInit()) + options = append(options, tflog.WithStderrFromInit()) + } + if conf.disableLogLocation { + sdkOptions = append(sdkOptions, tfsdklog.WithoutLocation()) + options = append(options, tflog.WithoutLocation()) + } return &server{ - downstream: serve, - stopCh: make(chan struct{}), + downstream: serve, + stopCh: make(chan struct{}), + tflogOpts: options, + tflogSDKOpts: sdkOptions, + name: name, } } func (s *server) GetSchema(ctx context.Context, req *tfplugin5.GetProviderSchema_Request) (*tfplugin5.GetProviderSchema_Response, error) { + ctx = rpcLoggingContext(s.loggingContext(ctx), "GetSchema") ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.GetProviderSchemaRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.GetProviderSchema(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.GetProviderSchema_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) PrepareProviderConfig(ctx context.Context, req *tfplugin5.PrepareProviderConfig_Request) (*tfplugin5.PrepareProviderConfig_Response, error) { + ctx = rpcLoggingContext(s.loggingContext(ctx), "PrepareProviderConfig") ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.PrepareProviderConfigRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.PrepareProviderConfig(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.PrepareProviderConfig_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) Configure(ctx context.Context, req *tfplugin5.Configure_Request) (*tfplugin5.Configure_Response, error) { + ctx = rpcLoggingContext(s.loggingContext(ctx), "Configure") ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ConfigureProviderRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ConfigureProvider(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.Configure_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil @@ -204,154 +333,228 @@ func (s *server) stop() { } func (s *server) Stop(ctx context.Context, req *tfplugin5.Stop_Request) (*tfplugin5.Stop_Response, error) { + ctx = rpcLoggingContext(s.loggingContext(ctx), "Stop") ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.StopProviderRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.StopProvider(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Closing all our contexts") s.stop() + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Closed all our contexts") ret, err := toproto.Stop_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ValidateDataSourceConfig(ctx context.Context, req *tfplugin5.ValidateDataSourceConfig_Request) (*tfplugin5.ValidateDataSourceConfig_Response, error) { + ctx = dataSourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "ValidateDataSourceConfig"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ValidateDataSourceConfigRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ValidateDataSourceConfig(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.ValidateDataSourceConfig_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ReadDataSource(ctx context.Context, req *tfplugin5.ReadDataSource_Request) (*tfplugin5.ReadDataSource_Response, error) { + ctx = dataSourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "ReadDataSource"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ReadDataSourceRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ReadDataSource(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.ReadDataSource_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ValidateResourceTypeConfig(ctx context.Context, req *tfplugin5.ValidateResourceTypeConfig_Request) (*tfplugin5.ValidateResourceTypeConfig_Response, error) { + ctx = resourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "ValidateResourceTypeConfig"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ValidateResourceTypeConfigRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ValidateResourceTypeConfig(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.ValidateResourceTypeConfig_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) UpgradeResourceState(ctx context.Context, req *tfplugin5.UpgradeResourceState_Request) (*tfplugin5.UpgradeResourceState_Response, error) { + ctx = resourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "UpgradeResourceState"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.UpgradeResourceStateRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.UpgradeResourceState(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.UpgradeResourceState_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ReadResource(ctx context.Context, req *tfplugin5.ReadResource_Request) (*tfplugin5.ReadResource_Response, error) { + ctx = resourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "ReadResource"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ReadResourceRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ReadResource(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.ReadResource_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) PlanResourceChange(ctx context.Context, req *tfplugin5.PlanResourceChange_Request) (*tfplugin5.PlanResourceChange_Response, error) { + ctx = resourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "PlanResourceChange"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.PlanResourceChangeRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.PlanResourceChange(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.PlanResourceChange_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ApplyResourceChange(ctx context.Context, req *tfplugin5.ApplyResourceChange_Request) (*tfplugin5.ApplyResourceChange_Response, error) { + ctx = resourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "ApplyResourceChange"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ApplyResourceChangeRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ApplyResourceChange(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.ApplyResourceChange_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ImportResourceState(ctx context.Context, req *tfplugin5.ImportResourceState_Request) (*tfplugin5.ImportResourceState_Response, error) { + ctx = resourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "ImportResourceState"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ImportResourceStateRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ImportResourceState(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.ImportResourceState_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil diff --git a/tfprotov6/server/plugin.go b/tfprotov6/server/plugin.go index afdb3f08..b5f60866 100644 --- a/tfprotov6/server/plugin.go +++ b/tfprotov6/server/plugin.go @@ -17,6 +17,8 @@ import ( // serve tfprotov6.ProviderServers as gRPC plugins for go-plugin. type GRPCProviderPlugin struct { GRPCProvider func() tfprotov6.ProviderServer + opts []ServeOpt + name string } // Server always returns an error; we're only implementing the GRPCPlugin @@ -40,6 +42,6 @@ func (p *GRPCProviderPlugin) GRPCClient(context.Context, *plugin.GRPCBroker, *gr // GRPCServer registers the gRPC provider server with the gRPC server that // go-plugin is standing up. func (p *GRPCProviderPlugin) GRPCServer(broker *plugin.GRPCBroker, s *grpc.Server) error { - tfplugin6.RegisterProviderServer(s, New(p.GRPCProvider())) + tfplugin6.RegisterProviderServer(s, New(p.name, p.GRPCProvider(), p.opts...)) return nil } diff --git a/tfprotov6/server/server.go b/tfprotov6/server/server.go index 2e907f5d..70f18c9a 100644 --- a/tfprotov6/server/server.go +++ b/tfprotov6/server/server.go @@ -4,14 +4,20 @@ import ( "context" "sync" - "github.com/hashicorp/go-hclog" - "github.com/hashicorp/go-plugin" "github.com/hashicorp/terraform-plugin-go/tfprotov6" "github.com/hashicorp/terraform-plugin-go/tfprotov6/internal/fromproto" "github.com/hashicorp/terraform-plugin-go/tfprotov6/internal/tfplugin6" "github.com/hashicorp/terraform-plugin-go/tfprotov6/internal/toproto" + + "github.com/hashicorp/go-hclog" + "github.com/hashicorp/go-plugin" + "github.com/hashicorp/go-uuid" + tflog "github.com/hashicorp/terraform-plugin-log" + tfsdklog "github.com/hashicorp/terraform-plugin-log/sdk" ) +const tflogSubsystemName = "proto" + // ServeOpt is an interface for defining options that can be passed to the // Serve function. Each implementation modifies the ServeConfig being // generated. A slice of ServeOpts then, cumulatively applied, render a full @@ -27,6 +33,9 @@ type ServeConfig struct { debugCtx context.Context debugCh chan *plugin.ReattachConfig debugCloseCh chan struct{} + + disableLogInitStderr bool + disableLogLocation bool } type serveConfigFunc func(*ServeConfig) error @@ -55,6 +64,26 @@ func WithGoPluginLogger(logger hclog.Logger) ServeOpt { }) } +// WithoutLogStderrOverride returns a ServeOpt that will disable the +// terraform-plugin-log behavior of logging to the stderr that existed at +// startup, not the stderr that exists when the logging statement is called. +func WithoutLogStderrOverride() ServeOpt { + return serveConfigFunc(func(in *ServeConfig) error { + in.disableLogInitStderr = true + return nil + }) +} + +// WithoutLogLocation returns a ServeOpt that will exclude file names and line +// numbers from log output for the terraform-plugin-log logs generated by the +// SDKs and provider. +func WithoutLogLocation() ServeOpt { + return serveConfigFunc(func(in *ServeConfig) error { + in.disableLogLocation = true + return nil + }) +} + // Serve starts a tfprotov6.ProviderServer serving, ready for Terraform to // connect to it. The name passed in should be the fully qualified name that // users will enter in the source field of the required_providers block, like @@ -81,6 +110,8 @@ func Serve(name string, serverFactory func() tfprotov6.ProviderServer, opts ...S Plugins: plugin.PluginSet{ "provider": &GRPCProviderPlugin{ GRPCProvider: serverFactory, + opts: opts, + name: name, }, }, GRPCServer: plugin.DefaultGRPCServer, @@ -105,6 +136,10 @@ type server struct { stopMu sync.Mutex stopCh chan struct{} + + tflogSDKOpts []tfsdklog.Option + tflogOpts []tflog.Option + name string } func mergeStop(ctx context.Context, cancel context.CancelFunc, stopCh chan struct{}) { @@ -130,60 +165,155 @@ func (s *server) stoppableContext(ctx context.Context) context.Context { return stoppable } +// loggingContext returns a context that wraps `ctx` and has +// terraform-plugin-log loggers injected. +func (s *server) loggingContext(ctx context.Context) context.Context { + // generate a request ID + reqID, err := uuid.GenerateUUID() + if err != nil { + reqID = "unable to assign request ID: " + err.Error() + } + + // set up the logger SDK loggers are derived from + ctx = tfsdklog.New(ctx, append([]tfsdklog.Option{ + tfsdklog.WithLevelFromEnv("TF", "LOG", "SDK"), + }, s.tflogSDKOpts...)...) + ctx = tfsdklog.With(ctx, "tf_req_id", reqID) + ctx = tfsdklog.With(ctx, "tf_provider_addr", s.name) + + // set up our protocol-level subsystem logger + ctx = tfsdklog.NewSubsystem(ctx, tflogSubsystemName, append([]tfsdklog.Option{ + tfsdklog.WithLevelFromEnv("TF", "LOG", "SDK", "PROTO"), + }, s.tflogSDKOpts...)...) + + // set up the provider logger + ctx = tflog.New(ctx, s.tflogOpts...) + ctx = tflog.With(ctx, "tf_req_id", reqID) + ctx = tflog.With(ctx, "tf_provider_addr", s.name) + return ctx +} + +func rpcLoggingContext(ctx context.Context, rpc string) context.Context { + ctx = tfsdklog.With(ctx, "tf_rpc", rpc) + ctx = tfsdklog.SubsystemWith(ctx, tflogSubsystemName, "tf_rpc", rpc) + ctx = tflog.With(ctx, "tf_rpc", rpc) + return ctx +} + +func resourceLoggingContext(ctx context.Context, resource string) context.Context { + ctx = tfsdklog.With(ctx, "tf_resource_type", resource) + ctx = tfsdklog.SubsystemWith(ctx, tflogSubsystemName, "tf_resource_type", resource) + ctx = tflog.With(ctx, "tf_resource_type", resource) + return ctx +} + +func dataSourceLoggingContext(ctx context.Context, dataSource string) context.Context { + ctx = tfsdklog.With(ctx, "tf_data_source_type", dataSource) + ctx = tfsdklog.SubsystemWith(ctx, tflogSubsystemName, "tf_data_source_type", dataSource) + ctx = tflog.With(ctx, "tf_data_source_type", dataSource) + return ctx +} + // New converts a tfprotov6.ProviderServer into a server capable of handling // Terraform protocol requests and issuing responses using the gRPC types. -func New(serve tfprotov6.ProviderServer) tfplugin6.ProviderServer { +func New(name string, serve tfprotov6.ProviderServer, opts ...ServeOpt) tfplugin6.ProviderServer { + var conf ServeConfig + for _, opt := range opts { + err := opt.ApplyServeOpt(&conf) + if err != nil { + // this should never happen, we already executed all + // this code as part of Serve + panic(err) + } + } + var sdkOptions []tfsdklog.Option + var options []tflog.Option + if !conf.disableLogInitStderr { + sdkOptions = append(sdkOptions, tfsdklog.WithStderrFromInit()) + options = append(options, tflog.WithStderrFromInit()) + } + if conf.disableLogLocation { + sdkOptions = append(sdkOptions, tfsdklog.WithoutLocation()) + options = append(options, tflog.WithoutLocation()) + } return &server{ - downstream: serve, - stopCh: make(chan struct{}), + downstream: serve, + stopCh: make(chan struct{}), + tflogOpts: options, + tflogSDKOpts: sdkOptions, + name: name, } } func (s *server) GetProviderSchema(ctx context.Context, req *tfplugin6.GetProviderSchema_Request) (*tfplugin6.GetProviderSchema_Response, error) { + ctx = rpcLoggingContext(s.loggingContext(ctx), "GetProviderSchema") ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.GetProviderSchemaRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.GetProviderSchema(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.GetProviderSchema_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ConfigureProvider(ctx context.Context, req *tfplugin6.ConfigureProvider_Request) (*tfplugin6.ConfigureProvider_Response, error) { + ctx = rpcLoggingContext(s.loggingContext(ctx), "ConfigureProvider") ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ConfigureProviderRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ConfigureProvider(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.Configure_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ValidateProviderConfig(ctx context.Context, req *tfplugin6.ValidateProviderConfig_Request) (*tfplugin6.ValidateProviderConfig_Response, error) { + ctx = rpcLoggingContext(s.loggingContext(ctx), "ValidateProviderConfig") + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ValidateProviderConfigRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ValidateProviderConfig(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.ValidateProviderConfig_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil @@ -203,154 +333,228 @@ func (s *server) stop() { } func (s *server) Stop(ctx context.Context, req *tfplugin6.StopProvider_Request) (*tfplugin6.StopProvider_Response, error) { + ctx = rpcLoggingContext(s.loggingContext(ctx), "Stop") ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.StopProviderRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.StopProvider(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Closing all our contexts") s.stop() + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Closed all our contexts") ret, err := toproto.Stop_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ValidateDataResourceConfig(ctx context.Context, req *tfplugin6.ValidateDataResourceConfig_Request) (*tfplugin6.ValidateDataResourceConfig_Response, error) { + ctx = dataSourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "ValidateDataResourceConfig"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ValidateDataResourceConfigRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ValidateDataResourceConfig(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.ValidateDataResourceConfig_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ReadDataSource(ctx context.Context, req *tfplugin6.ReadDataSource_Request) (*tfplugin6.ReadDataSource_Response, error) { + ctx = dataSourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "ReadDataSource"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ReadDataSourceRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ReadDataSource(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.ReadDataSource_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ValidateResourceConfig(ctx context.Context, req *tfplugin6.ValidateResourceConfig_Request) (*tfplugin6.ValidateResourceConfig_Response, error) { + ctx = resourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "ValidateResourceConfig"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ValidateResourceConfigRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ValidateResourceConfig(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.ValidateResourceConfig_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) UpgradeResourceState(ctx context.Context, req *tfplugin6.UpgradeResourceState_Request) (*tfplugin6.UpgradeResourceState_Response, error) { + ctx = resourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "UpgradeResourceState"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.UpgradeResourceStateRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.UpgradeResourceState(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.UpgradeResourceState_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ReadResource(ctx context.Context, req *tfplugin6.ReadResource_Request) (*tfplugin6.ReadResource_Response, error) { + ctx = resourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "ReadResource"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ReadResourceRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ReadResource(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.ReadResource_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) PlanResourceChange(ctx context.Context, req *tfplugin6.PlanResourceChange_Request) (*tfplugin6.PlanResourceChange_Response, error) { + ctx = resourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "PlanResourceChange"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.PlanResourceChangeRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.PlanResourceChange(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.PlanResourceChange_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ApplyResourceChange(ctx context.Context, req *tfplugin6.ApplyResourceChange_Request) (*tfplugin6.ApplyResourceChange_Response, error) { + ctx = resourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "ApplyResourceChange"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ApplyResourceChangeRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ApplyResourceChange(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.ApplyResourceChange_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil } func (s *server) ImportResourceState(ctx context.Context, req *tfplugin6.ImportResourceState_Request) (*tfplugin6.ImportResourceState_Response, error) { + ctx = resourceLoggingContext(rpcLoggingContext(s.loggingContext(ctx), "ImportResourceState"), req.TypeName) ctx = s.stoppableContext(ctx) + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Received request") + defer tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Served request") r, err := fromproto.ImportResourceStateRequest(req) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting request from protobuf", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Calling downstream") resp, err := s.downstream.ImportResourceState(ctx, r) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error from downstream", "error", err) return nil, err } + tfsdklog.SubsystemTrace(ctx, tflogSubsystemName, "Called downstream") ret, err := toproto.ImportResourceState_Response(resp) if err != nil { + tfsdklog.SubsystemError(ctx, tflogSubsystemName, "Error converting response to protobuf", "error", err) return nil, err } return ret, nil