unit tests

coder · mtojek · Mar 30, 2023 · Mar 28, 2023 · Mar 28, 2023 · Mar 28, 2023
commit 3a3147d2716bdb1c8b630b138463fdb590dc39c0
diff --git a/coderd/workspacebuilds_test.go b/coderd/workspacebuilds_test.go
@@ -1151,3 +1151,80 @@ func TestMigrateLegacyToRichParameters(t *testing.T) {
 	require.Len(t, buildParameters, 1)
 	require.Equal(t, "carrot", buildParameters[0].Value)
 }
+
+func TestWorkspaceBuildDebugMode(t *testing.T) {
+	t.Parallel()
+	client := coderdtest.New(t, &coderdtest.Options{IncludeProvisionerDaemon: true})
+	user := coderdtest.CreateFirstUser(t, client)
+	version := coderdtest.CreateTemplateVersion(t, client, user.OrganizationID, &echo.Responses{
+		Parse:         echo.ParseComplete,
+		ProvisionPlan: echo.ProvisionComplete,
+		ProvisionApply: []*proto.Provision_Response{{
+			Type: &proto.Provision_Response_Log{
+				Log: &proto.Log{
+					Level:  proto.LogLevel_DEBUG,
+					Output: "want-it",
+				},
+			},
+		}, {
+			Type: &proto.Provision_Response_Log{
+				Log: &proto.Log{
+					Level:  proto.LogLevel_TRACE,
+					Output: "dont-want-it",
+				},
+			},
+		}, {
+			Type: &proto.Provision_Response_Log{
+				Log: &proto.Log{
+					Level:  proto.LogLevel_DEBUG,
+					Output: "done",
+				},
+			},
+		}, {
+			Type: &proto.Provision_Response_Complete{
+				Complete: &proto.Provision_Complete{},
+			},
+		}},
+	})
+	template := coderdtest.CreateTemplate(t, client, user.OrganizationID, version.ID)
+	coderdtest.AwaitTemplateVersionJob(t, client, version.ID)
+
+	// Create workspace
+	workspace := coderdtest.CreateWorkspace(t, client, user.OrganizationID, template.ID)
+	coderdtest.AwaitWorkspaceBuildJob(t, client, workspace.LatestBuild.ID)
+
+	// Create workspace build
+	// ctx, cancel := context.WithTimeout(context.Background(), testutil.WaitLong)
+	//defer cancel()
+	ctx := context.Background()
+
+	build, err := client.CreateWorkspaceBuild(ctx, workspace.ID, codersdk.CreateWorkspaceBuildRequest{
+		TemplateVersionID: workspace.LatestBuild.TemplateVersionID,
+		Transition:        codersdk.WorkspaceTransitionStart,
+		ProvisionerState:  []byte(" "),
+		LogLevel:          "debug",
+	})
+	require.Nil(t, err)
+
+	build = coderdtest.AwaitWorkspaceBuildJob(t, client, build.ID)
+
+	// Watch for incoming logs
+	logs, closer, err := client.WorkspaceBuildLogsAfter(ctx, build.ID, 0)
+	require.NoError(t, err)
+	defer closer.Close()
+
+	for {
+		log, ok := <-logs
+		if !ok {
+			break
+		}
+
+		if log.Output == "dont-want-it" {
+			require.Failf(t, "unexpected log message", "%s log message shouldn't be logged: %s", log.Level, log.Output)
+		}
+
+		if log.Output == "done" {
+			return
+		}
+	}
+}
diff --git a/provisioner/echo/serve.go b/provisioner/echo/serve.go
@@ -192,7 +192,12 @@ func (e *echo) Provision(stream proto.DRPCProvisioner_ProvisionStream) error {
 		if err != nil {
 			return xerrors.Errorf("unmarshal: %w", err)
 		}
-		err = stream.Send(&response)
+		r, ok := filterLogResponses(config, &response)
+		if !ok {
+			continue
+		}
+
+		err = stream.Send(r)
 		if err != nil {
 			return err
 		}
@@ -282,3 +287,23 @@ func Tar(responses *Responses) ([]byte, error) {
 	}
 	return buffer.Bytes(), nil
 }
+
+func filterLogResponses(config *proto.Provision_Config, response *proto.Provision_Response) (*proto.Provision_Response, bool) {
+	responseLog, ok := response.Type.(*proto.Provision_Response_Log)
+	if !ok {
+		// Pass all non-log responses
+		return response, true
+	}
+
+	if config.ProvisionerLogLevel == "" {
+		// Don't change the default behavior of "echo"
+		return response, true
+	}
+
+	provisionerLogLevel := proto.LogLevel_value[strings.ToUpper(config.ProvisionerLogLevel)]
+	if int32(responseLog.Log.Level) < provisionerLogLevel {
+		// Log level is not enabled
+		return nil, false
+	}
+	return response, true
+}
diff --git a/provisioner/echo/serve_test.go b/provisioner/echo/serve_test.go
@@ -79,6 +79,7 @@ func TestEcho(t *testing.T) {
 		responses := []*proto.Provision_Response{{
 			Type: &proto.Provision_Response_Log{
 				Log: &proto.Log{
+					Level:  proto.LogLevel_INFO,
 					Output: "log-output",
 				},
 			},
@@ -115,6 +116,59 @@ func TestEcho(t *testing.T) {
 		require.Equal(t, responses[1].GetComplete().Resources[0].Name,
 			complete.GetComplete().Resources[0].Name)
 	})
+
+	t.Run("ProvisionWithLogLevel", func(t *testing.T) {
+		t.Parallel()
+
+		responses := []*proto.Provision_Response{{
+			Type: &proto.Provision_Response_Log{
+				Log: &proto.Log{
+					Level:  proto.LogLevel_TRACE,
+					Output: "log-output-trace",
+				},
+			},
+		}, {
+			Type: &proto.Provision_Response_Log{
+				Log: &proto.Log{
+					Level:  proto.LogLevel_INFO,
+					Output: "log-output-info",
+				},
+			},
+		}, {
+			Type: &proto.Provision_Response_Complete{
+				Complete: &proto.Provision_Complete{
+					Resources: []*proto.Resource{{
+						Name: "resource",
+					}},
+				},
+			},
+		}}
+		data, err := echo.Tar(&echo.Responses{
+			ProvisionApply: responses,
+		})
+		require.NoError(t, err)
+		client, err := api.Provision(ctx)
+		require.NoError(t, err)
+		err = client.Send(&proto.Provision_Request{
+			Type: &proto.Provision_Request_Plan{
+				Plan: &proto.Provision_Plan{
+					Config: &proto.Provision_Config{
+						Directory:           unpackTar(t, fs, data),
+						ProvisionerLogLevel: "debug",
+					},
+				},
+			},
+		})
+		require.NoError(t, err)
+		log, err := client.Recv()
+		require.NoError(t, err)
+		// Skip responses[0] as it's trace level
+		require.Equal(t, responses[1].GetLog().Output, log.GetLog().Output)
+		complete, err := client.Recv()
+		require.NoError(t, err)
+		require.Equal(t, responses[2].GetComplete().Resources[0].Name,
+			complete.GetComplete().Resources[0].Name)
+	})
 }
 
 func unpackTar(t *testing.T, fs afero.Fs, data []byte) string {

diff --git a/provisioner/terraform/executor.go b/provisioner/terraform/executor.go
@@ -473,7 +473,11 @@ func readAndLog(sink logSink, r io.Reader, done chan<- any, level proto.LogLevel
 
 		logLevel := convertTerraformLogLevel(log.Level, sink)
 		if logLevel == proto.LogLevel_TRACE {
-			continue // skip TRACE log entries as they produce a lot of noise
+			// Skip TRACE log entries as they produce a lot of noise
+			//
+			// FIXME consider config.ProvisionerLogLevel to enable custom level logging
+			// instead of "just-debug-level" mode.
+			continue
 		}
 
 		// Degrade JSON log entries marked as INFO as these are logs produced in debug mode.

diff --git a/provisioner/terraform/provision.go b/provisioner/terraform/provision.go
@@ -239,8 +239,6 @@ func provisionEnv(config *proto.Provision_Config, params []*proto.ParameterValue
 
 	if logLevel == "debug" {
 		// TF_LOG=JSON enables all kind of logging: trace-debug-info-warn-error.
-		// Coder shows info-warn-error by default, so we need to filter "trace" log entries,
-		// on the upper layer.
 		// The idea behind using TF_LOG=JSON instead of TF_LOG=debug is ensuring the proper log format.
 		env = append(env, "TF_LOG=JSON")
 	}