helper/resource: Added terraform-plugin-log logger and extensive log entries (#891)

Reference: #838

This new subsystem logger is meant for instrumenting the acceptance testing framework. Most of the changes are to support passing the context to many of the functions and adding `DEBUG`/`TRACE` log entries for provider developer and SDK maintainer troubleshooting.

Verified `go test` logging behaviors via terraform-provider-corner:

- No logs by default
- `TF_LOG_SDK_HELPER_RESOURCE` environment variable control of new logger
- `TF_LOG` enabling new logger
- `TF_ACC_LOG_PATH` enabling new logger

Author: bflad

.changelog/891.txt

@@ -0,0 +1,7 @@
+```release-note:note
+helper/resource: The new terraform-plugin-log `sdk.helper_resource` logger inherits the `TF_LOG`, `TF_LOG_PATH_MASK`, and `TF_ACC_LOG_PATH` environment variable settings, similar to the prior logging. The `TF_LOG_SDK_HELPER_RESOURCE` environment variable can be used to separately control the new logger level.
+```
+
+```release-note:enhancement
+helper/resource: Added terraform-plugin-log `sdk.helper_resource` logger and extensive `TRACE` log entries
+```

helper/logging/logging.go

@@ -1,7 +1,6 @@
 package logging
 
 import (
-	"context"
 	"fmt"
 	"io"
 	"io/ioutil"
@@ -11,7 +10,6 @@ import (
 	"syscall"
 
 	"github.com/hashicorp/logutils"
-	"github.com/hashicorp/terraform-plugin-log/tfsdklog"
 	testing "github.com/mitchellh/go-testing-interface"
 )
 
@@ -138,12 +136,3 @@ func isValidLogLevel(level string) bool {
 
 	return false
 }
-
-// GetTestLogContext creates a context that is registered to the SDK log sink.
-// This function is for internal usage only and is not supported by the project's
-// compatibility promises.
-func GetTestLogContext(t testing.T) context.Context {
-	ctx := context.Background()
-	ctx = tfsdklog.RegisterTestSink(ctx, t)
-	return ctx
-}

helper/resource/plugin.go

@@ -13,7 +13,6 @@ import (
 	"github.com/hashicorp/terraform-exec/tfexec"
 	"github.com/hashicorp/terraform-plugin-go/tfprotov5"
 	"github.com/hashicorp/terraform-plugin-go/tfprotov6"
-	"github.com/hashicorp/terraform-plugin-sdk/v2/helper/logging"
 	"github.com/hashicorp/terraform-plugin-sdk/v2/helper/schema"
 	"github.com/hashicorp/terraform-plugin-sdk/v2/internal/plugintest"
 	"github.com/hashicorp/terraform-plugin-sdk/v2/plugin"
@@ -26,7 +25,7 @@ type providerFactories struct {
 	protov6 map[string]func() (tfprotov6.ProviderServer, error)
 }
 
-func runProviderCommand(t testing.T, f func() error, wd *plugintest.WorkingDir, factories providerFactories) error {
+func runProviderCommand(ctx context.Context, t testing.T, f func() error, wd *plugintest.WorkingDir, factories providerFactories) error {
 	// don't point to this as a test failure location
 	// point to whatever called it
 	t.Helper()
@@ -35,7 +34,7 @@ func runProviderCommand(t testing.T, f func() error, wd *plugintest.WorkingDir,
 	// reattach behavior in Terraform. This ensures we get test coverage
 	// and enables the use of delve as a debugger.
 
-	ctx, cancel := context.WithCancel(logging.GetTestLogContext(t))
+	ctx, cancel := context.WithCancel(ctx)
 	defer cancel()
 
 	// this is needed so Terraform doesn't default to expecting protocol 4;

helper/resource/testing.go

@@ -1,6 +1,7 @@
 package resource
 
 import (
+	"context"
 	"errors"
 	"flag"
 	"fmt"
@@ -16,9 +17,9 @@ import (
 
 	"github.com/hashicorp/terraform-plugin-go/tfprotov5"
 	"github.com/hashicorp/terraform-plugin-go/tfprotov6"
-	"github.com/hashicorp/terraform-plugin-sdk/v2/helper/logging"
 	"github.com/hashicorp/terraform-plugin-sdk/v2/helper/schema"
 	"github.com/hashicorp/terraform-plugin-sdk/v2/internal/addrs"
+	"github.com/hashicorp/terraform-plugin-sdk/v2/internal/logging"
 	"github.com/hashicorp/terraform-plugin-sdk/v2/internal/plugintest"
 	"github.com/hashicorp/terraform-plugin-sdk/v2/terraform"
 )
@@ -583,6 +584,9 @@ func ParallelTest(t testing.T, c TestCase) {
 func Test(t testing.T, c TestCase) {
 	t.Helper()
 
+	ctx := context.Background()
+	ctx = logging.InitTestContext(ctx, t)
+
 	// We only run acceptance tests if an env var is set because they're
 	// slow and generally require some outside configuration. You can opt out
 	// of this with OverrideEnvVar on individual TestCases.
@@ -593,8 +597,6 @@ func Test(t testing.T, c TestCase) {
 		return
 	}
 
-	logging.SetOutput(t)
-
 	// Copy any explicitly passed providers to factories, this is for backwards compatibility.
 	if len(c.Providers) > 0 {
 		c.ProviderFactories = map[string]func() (*schema.Provider, error){}
@@ -610,26 +612,34 @@ func Test(t testing.T, c TestCase) {
 		}
 	}
 
+	logging.HelperResourceDebug(ctx, "Starting TestCase")
+
 	// Run the PreCheck if we have it.
 	// This is done after the auto-configure to allow providers
 	// to override the default auto-configure parameters.
 	if c.PreCheck != nil {
+		logging.HelperResourceDebug(ctx, "Calling TestCase PreCheck")
+
 		c.PreCheck()
+
+		logging.HelperResourceDebug(ctx, "Called TestCase PreCheck")
 	}
 
 	sourceDir, err := os.Getwd()
 	if err != nil {
 		t.Fatalf("Error getting working dir: %s", err)
 	}
-	helper := plugintest.AutoInitProviderHelper(sourceDir)
+	helper := plugintest.AutoInitProviderHelper(ctx, sourceDir)
 	defer func(helper *plugintest.Helper) {
 		err := helper.Close()
 		if err != nil {
-			log.Printf("Error cleaning up temporary test files: %s", err)
+			logging.HelperResourceError(ctx, "Unable to clean up temporary test files", logging.KeyError, err)
 		}
 	}(helper)
 
-	runNewTest(t, c, helper)
+	runNewTest(ctx, t, c, helper)
+
+	logging.HelperResourceDebug(ctx, "Finished TestCase")
 }
 
 // testProviderConfig takes the list of Providers in a TestCase and returns a

helper/resource/testing_config.go

@@ -1,14 +1,21 @@
 package resource
 
 import (
+	"context"
 	"errors"
 	"fmt"
-	"log"
 
+	"github.com/hashicorp/terraform-plugin-sdk/v2/internal/logging"
 	"github.com/hashicorp/terraform-plugin-sdk/v2/terraform"
 )
 
-func testStepTaint(state *terraform.State, step TestStep) error {
+func testStepTaint(ctx context.Context, state *terraform.State, step TestStep) error {
+	if len(step.Taint) == 0 {
+		return nil
+	}
+
+	logging.HelperResourceTrace(ctx, fmt.Sprintf("Using TestStep Taint: %v", step.Taint))
+
 	for _, p := range step.Taint {
 		m := state.RootModule()
 		if m == nil {
@@ -18,7 +25,7 @@ func testStepTaint(state *terraform.State, step TestStep) error {
 		if !ok {
 			return fmt.Errorf("resource %q not found in state", p)
 		}
-		log.Printf("[WARN] Test: Explicitly tainting resource %q", p)
+		logging.HelperResourceWarn(ctx, fmt.Sprintf("Explicitly tainting resource %q", p))
 		rs.Taint()
 	}
 	return nil