Initial implementation of structured logging in cloud backend (#32504)

* Implementation of structured logging.

These are the changes that enable the cloud backend to consume
structured logs and make use of the new plan renderer. This will enable
CLI-driven runs to view the structured output in the Terraform Cloud UI.

* Cloud structured logging unit tests

* Remove deferred logs logic, fix minor issues

Color formatting fixes, log type stop lists, default behavior for logs
that are unknown

* Use service disco path in redacted plan url

go.mod

@@ -38,12 +38,13 @@ require (
 	github.com/hashicorp/go-hclog v0.15.0
 	github.com/hashicorp/go-multierror v1.1.1
 	github.com/hashicorp/go-plugin v1.4.3
-	github.com/hashicorp/go-retryablehttp v0.7.1
-	github.com/hashicorp/go-tfe v1.14.0
+	github.com/hashicorp/go-retryablehttp v0.7.2
+	github.com/hashicorp/go-tfe v1.18.0
 	github.com/hashicorp/go-uuid v1.0.3
 	github.com/hashicorp/go-version v1.6.0
 	github.com/hashicorp/hcl v0.0.0-20170504190234-a4b07c25de5f
 	github.com/hashicorp/hcl/v2 v2.16.0
+	github.com/hashicorp/jsonapi v0.0.0-20210826224640-ee7dae0fb22d
 	github.com/hashicorp/terraform-config-inspect v0.0.0-20210209133302-4fd17a0faac2
 	github.com/hashicorp/terraform-registry-address v0.0.0-20220623143253-7d51757b572c
 	github.com/hashicorp/terraform-svchost v0.1.0
@@ -147,7 +148,6 @@ require (
 	github.com/hashicorp/go-safetemp v1.0.0 // indirect
 	github.com/hashicorp/go-slug v0.10.1 // indirect
 	github.com/hashicorp/golang-lru v0.5.1 // indirect
-	github.com/hashicorp/jsonapi v0.0.0-20210826224640-ee7dae0fb22d // indirect
 	github.com/hashicorp/serf v0.9.5 // indirect
 	github.com/hashicorp/yamux v0.0.0-20181012175058-2f1d1f20f75d // indirect
 	github.com/huandu/xstrings v1.3.3 // indirect
@@ -175,7 +175,7 @@ require (
 	github.com/vmihailenco/tagparser v0.1.1 // indirect
 	go.opencensus.io v0.23.0 // indirect
 	golang.org/x/exp/typeparams v0.0.0-20220218215828-6cf2b201936e // indirect
-	golang.org/x/time v0.1.0 // indirect
+	golang.org/x/time v0.3.0 // indirect
 	golang.org/x/xerrors v0.0.0-20220907171357-04be3eba64a2 // indirect
 	google.golang.org/appengine v1.6.7 // indirect
 	gopkg.in/check.v1 v1.0.0-20201130134442-10cb98267c6c // indirect

go.sum

@@ -365,8 +365,8 @@ github.com/hashicorp/go-multierror v1.1.1/go.mod h1:iw975J/qwKPdAO1clOe2L8331t/9
 github.com/hashicorp/go-plugin v1.4.3 h1:DXmvivbWD5qdiBts9TpBC7BYL1Aia5sxbRgQB+v6UZM=
 github.com/hashicorp/go-plugin v1.4.3/go.mod h1:5fGEH17QVwTTcR0zV7yhDPLLmFX9YSZ38b18Udy6vYQ=
 github.com/hashicorp/go-retryablehttp v0.7.0/go.mod h1:vAew36LZh98gCBJNLH42IQ1ER/9wtLZZ8meHqQvEYWY=
-github.com/hashicorp/go-retryablehttp v0.7.1 h1:sUiuQAnLlbvmExtFQs72iFW/HXeUn8Z1aJLQ4LJJbTQ=
-github.com/hashicorp/go-retryablehttp v0.7.1/go.mod h1:vAew36LZh98gCBJNLH42IQ1ER/9wtLZZ8meHqQvEYWY=
+github.com/hashicorp/go-retryablehttp v0.7.2 h1:AcYqCvkpalPnPF2pn0KamgwamS42TqUDDYFRKq/RAd0=
+github.com/hashicorp/go-retryablehttp v0.7.2/go.mod h1:Jy/gPYAdjqffZ/yFGCFV2doI5wjtH1ewM9u8iYVjtX8=
 github.com/hashicorp/go-rootcerts v1.0.2 h1:jzhAVGtqPKbwpyCPELlgNWhE1znq+qwJtW5Oi2viEzc=
 github.com/hashicorp/go-rootcerts v1.0.2/go.mod h1:pqUvnprVnM5bf7AOirdbb01K4ccR319Vf4pU3K5EGc8=
 github.com/hashicorp/go-safetemp v1.0.0 h1:2HR189eFNrjHQyENnQMMpCiBAsRxzbTMIgBhEyExpmo=
@@ -376,8 +376,8 @@ github.com/hashicorp/go-slug v0.10.1/go.mod h1:Ib+IWBYfEfJGI1ZyXMGNbu2BU+aa3Dzu4
 github.com/hashicorp/go-sockaddr v1.0.0 h1:GeH6tui99pF4NJgfnhp+L6+FfobzVW3Ah46sLo0ICXs=
 github.com/hashicorp/go-sockaddr v1.0.0/go.mod h1:7Xibr9yA9JjQq1JpNB2Vw7kxv8xerXegt+ozgdvDeDU=
 github.com/hashicorp/go-syslog v1.0.0/go.mod h1:qPfqrKkXGihmCqbJM2mZgkZGvKG1dFdvsLplgctolz4=
-github.com/hashicorp/go-tfe v1.14.0 h1:FZKKkwlyTxw8/OE3e7NiFQLcgGXTHra9ogGhMTotxh8=
-github.com/hashicorp/go-tfe v1.14.0/go.mod h1:77snluBqtTTvMrY0w/mxQA5jlHQ8NT44AqQ8UdrPf0o=
+github.com/hashicorp/go-tfe v1.18.0 h1:AjyZe2KSAyGHD1kbGYlY64PVYQPnJJON24qr97IjIqA=
+github.com/hashicorp/go-tfe v1.18.0/go.mod h1:T76X7dHKNEPEugPCZI3gDdaDdxUU4P4sqMZO60W57cQ=
 github.com/hashicorp/go-uuid v1.0.0/go.mod h1:6SBZvOh/SIDV7/2o3Jml5SYk/TvGqwFJ/bN7x4byOro=
 github.com/hashicorp/go-uuid v1.0.1/go.mod h1:6SBZvOh/SIDV7/2o3Jml5SYk/TvGqwFJ/bN7x4byOro=
 github.com/hashicorp/go-uuid v1.0.2/go.mod h1:6SBZvOh/SIDV7/2o3Jml5SYk/TvGqwFJ/bN7x4byOro=
@@ -864,8 +864,8 @@ golang.org/x/time v0.0.0-20181108054448-85acf8d2951c/go.mod h1:tRJNPiyCQ0inRvYxb
 golang.org/x/time v0.0.0-20190308202827-9d24e82272b4/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ=
 golang.org/x/time v0.0.0-20191024005414-555d28b269f0/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ=
 golang.org/x/time v0.0.0-20210723032227-1f47c861a9ac/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ=
-golang.org/x/time v0.1.0 h1:xYY+Bajn2a7VBmTM5GikTmnK8ZuX8YgnQCqZpbBNtmA=
-golang.org/x/time v0.1.0/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ=
+golang.org/x/time v0.3.0 h1:rg5rLMjNzMS1RkNLzCG38eapWhnYLFYXDXj2gOlr8j4=
+golang.org/x/time v0.3.0/go.mod h1:tRJNPiyCQ0inRvYxbN9jk5I+vvW/OXSQhTDSoE431IQ=
 golang.org/x/tools v0.0.0-20180917221912-90fa682c2a6e/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
 golang.org/x/tools v0.0.0-20190114222345-bf090417da8b/go.mod h1:n7NCudcB/nEzxVGmLbDWY5pfWTLqBcC2KZ6jyYvM4mQ=
 golang.org/x/tools v0.0.0-20190226205152-f727befe758c/go.mod h1:9Yl7xja0Znq3iFh3HoIrodX9oNMXvdceNzlUR8zjMvY=

internal/cloud/backend.go

@@ -23,6 +23,7 @@ import (
 	"github.com/zclconf/go-cty/cty/gocty"
 
 	"github.com/hashicorp/terraform/internal/backend"
+	"github.com/hashicorp/terraform/internal/command/jsonformat"
 	"github.com/hashicorp/terraform/internal/configs/configschema"
 	"github.com/hashicorp/terraform/internal/plans"
 	"github.com/hashicorp/terraform/internal/states/statemgr"
@@ -75,6 +76,9 @@ type Cloud struct {
 	// services is used for service discovery
 	services *disco.Disco
 
+	// renderer is used for rendering JSON plan output and streamed logs.
+	renderer *jsonformat.Renderer
+
 	// local allows local operations, where Terraform Cloud serves as a state storage backend.
 	local backend.Enhanced
 

internal/cloud/backend_apply.go

@@ -3,11 +3,13 @@ package cloud
 import (
 	"bufio"
 	"context"
+	"encoding/json"
 	"io"
 	"log"
 
 	tfe "github.com/hashicorp/go-tfe"
 	"github.com/hashicorp/terraform/internal/backend"
+	"github.com/hashicorp/terraform/internal/command/jsonformat"
 	"github.com/hashicorp/terraform/internal/plans"
 	"github.com/hashicorp/terraform/internal/terraform"
 	"github.com/hashicorp/terraform/internal/tfdiags"
@@ -151,41 +153,70 @@ func (b *Cloud) opApply(stopCtx, cancelCtx context.Context, op *backend.Operatio
 		return r, err
 	}
 
-	logs, err := b.client.Applies.Logs(stopCtx, r.Apply.ID)
+	err = b.renderApplyLogs(stopCtx, r)
 	if err != nil {
-		return r, generalError("Failed to retrieve logs", err)
+		return r, err
+	}
+
+	return r, nil
+}
+
+func (b *Cloud) renderApplyLogs(ctx context.Context, run *tfe.Run) error {
+	logs, err := b.client.Applies.Logs(ctx, run.Apply.ID)
+	if err != nil {
+		return err
 	}
-	reader := bufio.NewReaderSize(logs, 64*1024)
 
 	if b.CLI != nil {
+		reader := bufio.NewReaderSize(logs, 64*1024)
 		skip := 0
+
 		for next := true; next; {
 			var l, line []byte
+			var err error
 
 			for isPrefix := true; isPrefix; {
 				l, isPrefix, err = reader.ReadLine()
 				if err != nil {
 					if err != io.EOF {
-						return r, generalError("Failed to read logs", err)
+						return generalError("Failed to read logs", err)
 					}
 					next = false
 				}
+
 				line = append(line, l...)
 			}
 
-			// Skip the first 3 lines to prevent duplicate output.
+			// Apply logs show the same Terraform info logs as shown in the plan logs
+			// (which contain version and os/arch information), we therefore skip to prevent duplicate output.
 			if skip < 3 {
 				skip++
 				continue
 			}
 
 			if next || len(line) > 0 {
-				b.CLI.Output(b.Colorize().Color(string(line)))
+				log := &jsonformat.JSONLog{}
+				if err := json.Unmarshal(line, log); err != nil {
+					// If we can not parse the line as JSON, we will simply
+					// print the line. This maintains backwards compatibility for
+					// users who do not wish to enable structured output in their
+					// workspace.
+					b.CLI.Output(string(line))
+					continue
+				}
+
+				if b.renderer != nil {
+					// Otherwise, we will print the log
+					err := b.renderer.RenderLog(log)
+					if err != nil {
+						return err
+					}
+				}
 			}
 		}
 	}
 
-	return r, nil
+	return nil
 }
 
 const applyDefaultHeader = `

internal/cloud/backend_apply_test.go

@@ -19,6 +19,7 @@ import (
 	"github.com/hashicorp/terraform/internal/backend"
 	"github.com/hashicorp/terraform/internal/command/arguments"
 	"github.com/hashicorp/terraform/internal/command/clistate"
+	"github.com/hashicorp/terraform/internal/command/jsonformat"
 	"github.com/hashicorp/terraform/internal/command/views"
 	"github.com/hashicorp/terraform/internal/depsfile"
 	"github.com/hashicorp/terraform/internal/initwd"
@@ -114,6 +115,153 @@ func TestCloud_applyBasic(t *testing.T) {
 	}
 }
 
+func TestCloud_applyJSONBasic(t *testing.T) {
+	b, bCleanup := testBackendWithName(t)
+	defer bCleanup()
+
+	stream, close := terminal.StreamsForTesting(t)
+
+	b.renderer = &jsonformat.Renderer{
+		Streams:  stream,
+		Colorize: mockColorize(),
+	}
+
+	op, configCleanup, done := testOperationApply(t, "./testdata/apply-json")
+	defer configCleanup()
+	defer done(t)
+
+	input := testInput(t, map[string]string{
+		"approve": "yes",
+	})
+
+	op.UIIn = input
+	op.UIOut = b.CLI
+	op.Workspace = testBackendSingleWorkspaceName
+
+	mockSROWorkspace(t, b, op.Workspace)
+
+	run, err := b.Operation(context.Background(), op)
+	if err != nil {
+		t.Fatalf("error starting operation: %v", err)
+	}
+
+	<-run.Done()
+	if run.Result != backend.OperationSuccess {
+		t.Fatalf("operation failed: %s", b.CLI.(*cli.MockUi).ErrorWriter.String())
+	}
+	if run.PlanEmpty {
+		t.Fatalf("expected a non-empty plan")
+	}
+
+	if len(input.answers) > 0 {
+		t.Fatalf("expected no unused answers, got: %v", input.answers)
+	}
+
+	outp := close(t)
+	gotOut := outp.Stdout()
+
+	if !strings.Contains(gotOut, "1 to add, 0 to change, 0 to destroy") {
+		t.Fatalf("expected plan summary in output: %s", gotOut)
+	}
+	if !strings.Contains(gotOut, "1 added, 0 changed, 0 destroyed") {
+		t.Fatalf("expected apply summary in output: %s", gotOut)
+	}
+
+	stateMgr, _ := b.StateMgr(testBackendSingleWorkspaceName)
+	// An error suggests that the state was not unlocked after apply
+	if _, err := stateMgr.Lock(statemgr.NewLockInfo()); err != nil {
+		t.Fatalf("unexpected error locking state after apply: %s", err.Error())
+	}
+}
+
+func TestCloud_applyJSONWithOutputs(t *testing.T) {
+	b, bCleanup := testBackendWithName(t)
+	defer bCleanup()
+
+	stream, close := terminal.StreamsForTesting(t)
+
+	b.renderer = &jsonformat.Renderer{
+		Streams:  stream,
+		Colorize: mockColorize(),
+	}
+
+	op, configCleanup, done := testOperationApply(t, "./testdata/apply-json-with-outputs")
+	defer configCleanup()
+	defer done(t)
+
+	input := testInput(t, map[string]string{
+		"approve": "yes",
+	})
+
+	op.UIIn = input
+	op.UIOut = b.CLI
+	op.Workspace = testBackendSingleWorkspaceName
+
+	mockSROWorkspace(t, b, op.Workspace)
+
+	run, err := b.Operation(context.Background(), op)
+	if err != nil {
+		t.Fatalf("error starting operation: %v", err)
+	}
+
+	<-run.Done()
+	if run.Result != backend.OperationSuccess {
+		t.Fatalf("operation failed: %s", b.CLI.(*cli.MockUi).ErrorWriter.String())
+	}
+	if run.PlanEmpty {
+		t.Fatalf("expected a non-empty plan")
+	}
+
+	if len(input.answers) > 0 {
+		t.Fatalf("expected no unused answers, got: %v", input.answers)
+	}
+
+	outp := close(t)
+	gotOut := outp.Stdout()
+	expectedSimpleOutput := `simple = [
+        "some",
+        "list",
+    ]`
+	expectedSensitiveOutput := `secret = (sensitive value)`
+	expectedComplexOutput := `complex = {
+        keyA = {
+            someList = [
+                1,
+                2,
+                3,
+            ]
+        }
+        keyB = {
+            someBool = true
+            someStr  = "hello"
+        }
+    }`
+
+	if !strings.Contains(gotOut, "1 to add, 0 to change, 0 to destroy") {
+		t.Fatalf("expected plan summary in output: %s", gotOut)
+	}
+	if !strings.Contains(gotOut, "1 added, 0 changed, 0 destroyed") {
+		t.Fatalf("expected apply summary in output: %s", gotOut)
+	}
+	if !strings.Contains(gotOut, "Outputs:") {
+		t.Fatalf("expected output header: %s", gotOut)
+	}
+	if !strings.Contains(gotOut, expectedSimpleOutput) {
+		t.Fatalf("expected output: %s, got: %s", expectedSimpleOutput, gotOut)
+	}
+	if !strings.Contains(gotOut, expectedSensitiveOutput) {
+		t.Fatalf("expected output: %s, got: %s", expectedSensitiveOutput, gotOut)
+	}
+	if !strings.Contains(gotOut, expectedComplexOutput) {
+		t.Fatalf("expected output: %s, got: %s", expectedComplexOutput, gotOut)
+	}
+	stateMgr, _ := b.StateMgr(testBackendSingleWorkspaceName)
+	// An error suggests that the state was not unlocked after apply
+	if _, err := stateMgr.Lock(statemgr.NewLockInfo()); err != nil {
+		t.Fatalf("unexpected error locking state after apply: %s", err.Error())
+	}
+}
+
 func TestCloud_applyCanceled(t *testing.T) {
 	b, bCleanup := testBackendWithName(t)
 	defer bCleanup()
@@ -1443,6 +1591,46 @@ func TestCloud_applyWithRemoteError(t *testing.T) {
 	}
 }
 
+func TestCloud_applyJSONWithRemoteError(t *testing.T) {
+	b, bCleanup := testBackendWithName(t)
+	defer bCleanup()
+
+	stream, close := terminal.StreamsForTesting(t)
+
+	b.renderer = &jsonformat.Renderer{
+		Streams:  stream,
+		Colorize: mockColorize(),
+	}
+
+	op, configCleanup, done := testOperationApply(t, "./testdata/apply-json-with-error")
+	defer configCleanup()
+	defer done(t)
+
+	op.Workspace = testBackendSingleWorkspaceName
+
+	mockSROWorkspace(t, b, op.Workspace)
+
+	run, err := b.Operation(context.Background(), op)
+	if err != nil {
+		t.Fatalf("error starting operation: %v", err)
+	}
+
+	<-run.Done()
+	if run.Result == backend.OperationSuccess {
+		t.Fatal("expected apply operation to fail")
+	}
+	if run.Result.ExitStatus() != 1 {
+		t.Fatalf("expected exit code 1, got %d", run.Result.ExitStatus())
+	}
+
+	outp := close(t)
+	gotOut := outp.Stdout()
+
+	if !strings.Contains(gotOut, "Unsupported block type") {
+		t.Fatalf("unexpected plan error in output: %s", gotOut)
+	}
+}
+
 func TestCloud_applyVersionCheck(t *testing.T) {
 	testCases := map[string]struct {
 		localVersion  string