chore: improve logging around lifecycle scripts (#420)

Author: johnstcn

envbuilder.go

@@ -169,6 +169,7 @@ func run(ctx context.Context, opts options.Options, execArgs *execArgsInfo) erro
 		RemoteEnv:    make(map[string]string),
 	}
 	if fileExists(opts.Filesystem, workingDir.Image()) {
+		opts.Logger(log.LevelInfo, "Found magic image file at %s", workingDir.Image())
 		if err = parseMagicImageFile(opts.Filesystem, workingDir.Image(), &runtimeData); err != nil {
 			return fmt.Errorf("parse magic image file: %w", err)
 		}
@@ -287,6 +288,7 @@ func run(ctx context.Context, opts options.Options, execArgs *execArgsInfo) erro
 
 		var buildParams *devcontainer.Compiled
 		if opts.DockerfilePath == "" {
+			opts.Logger(log.LevelInfo, "No Dockerfile specified, looking for a devcontainer.json...")
 			// Only look for a devcontainer if a Dockerfile wasn't specified.
 			// devcontainer is a standard, so it's reasonable to be the default.
 			var devcontainerDir string
@@ -296,6 +298,7 @@ func run(ctx context.Context, opts options.Options, execArgs *execArgsInfo) erro
 				opts.Logger(log.LevelError, "Failed to locate devcontainer.json: %s", err.Error())
 				opts.Logger(log.LevelError, "Falling back to the default image...")
 			} else {
+				opts.Logger(log.LevelInfo, "Building in Devcontainer mode using %s", strings.TrimPrefix(runtimeData.DevcontainerPath, buildTimeWorkspaceFolder))
 				// We know a devcontainer exists.
 				// Let's parse it and use it!
 				file, err := opts.Filesystem.Open(runtimeData.DevcontainerPath)
@@ -334,6 +337,7 @@ func run(ctx context.Context, opts options.Options, execArgs *execArgsInfo) erro
 		} else {
 			// If a Dockerfile was specified, we use that.
 			dockerfilePath := filepath.Join(buildTimeWorkspaceFolder, opts.DockerfilePath)
+			opts.Logger(log.LevelInfo, "Building in Dockerfile-only mode using %s", opts.DockerfilePath)
 
 			// If the dockerfilePath is specified and deeper than the base of WorkspaceFolder AND the BuildContextPath is
 			// not defined, show a warning
@@ -1406,6 +1410,7 @@ func execOneLifecycleScript(
 	userInfo userInfo,
 ) error {
 	if s.IsEmpty() {
+		logf(log.LevelInfo, "=== No %s script specified", scriptName)
 		return nil
 	}
 	logf(log.LevelInfo, "=== Running %s as the %q user...", scriptName, userInfo.user.Username)
@@ -1424,6 +1429,7 @@ func execLifecycleScripts(
 	userInfo userInfo,
 ) error {
 	if options.PostStartScriptPath != "" {
+		options.Logger(log.LevelDebug, "Removing postStartScriptPath %s", options.PostStartScriptPath)
 		_ = os.Remove(options.PostStartScriptPath)
 	}
 
@@ -1432,6 +1438,8 @@ func execLifecycleScripts(
 			// skip remaining lifecycle commands
 			return nil
 		}
+	} else {
+		options.Logger(log.LevelDebug, "Skipping onCreateCommand for subsequent starts...")
 	}
 	if err := execOneLifecycleScript(ctx, options.Logger, scripts.UpdateContentCommand, "updateContentCommand", userInfo); err != nil {
 		// skip remaining lifecycle commands

integration/integration_test.go

@@ -1188,37 +1188,88 @@ func TestBuildSecrets(t *testing.T) {
 func TestLifecycleScripts(t *testing.T) {
 	t.Parallel()
 
-	// Ensures that a Git repository with a devcontainer.json is cloned and built.
-	srv := gittest.CreateGitServer(t, gittest.Options{
-		Files: map[string]string{
-			".devcontainer/devcontainer.json": `{
-				"name": "Test",
-				"build": {
-					"dockerfile": "Dockerfile"
-				},
-				"onCreateCommand": "echo create > /tmp/out",
-				"updateContentCommand": ["sh", "-c", "echo update >> /tmp/out"],
-				"postCreateCommand": "(echo -n postCreate. ; id -un) >> /tmp/out",
-				"postStartCommand": {
-					"parallel1": "echo parallel1 > /tmp/parallel1",
-					"parallel2": ["sh", "-c", "echo parallel2 > /tmp/parallel2"]
-				}
-			}`,
-			".devcontainer/Dockerfile": "FROM " + testImageAlpine + "\nUSER nobody",
+	for _, tt := range []struct {
+		name         string
+		files        map[string]string
+		outputCmd    string
+		expectOutput string
+	}{
+		{
+			name: "build",
+			files: map[string]string{
+				".devcontainer/devcontainer.json": `{
+					"name": "Test",
+					"build": {
+						"dockerfile": "Dockerfile"
+					},
+					"onCreateCommand": "echo create > /tmp/out",
+					"updateContentCommand": ["sh", "-c", "echo update >> /tmp/out"],
+					"postCreateCommand": "(echo -n postCreate. ; id -un) >> /tmp/out",
+					"postStartCommand": {
+						"parallel1": "echo parallel1 > /tmp/parallel1",
+						"parallel2": ["sh", "-c", "echo parallel2 > /tmp/parallel2"]
+					}
+				}`,
+				".devcontainer/Dockerfile": "FROM " + testImageAlpine + "\nUSER nobody",
+			},
+			outputCmd:    "cat /tmp/out /tmp/parallel1 /tmp/parallel2",
+			expectOutput: "create\nupdate\npostCreate.nobody\nparallel1\nparallel2",
 		},
-	})
-	ctr, err := runEnvbuilder(t, runOpts{env: []string{
-		envbuilderEnv("GIT_URL", srv.URL),
-	}})
-	require.NoError(t, err)
-
-	output := execContainer(t, ctr, "cat /tmp/out /tmp/parallel1 /tmp/parallel2")
-	require.Equal(t,
-		`create
-update
-postCreate.nobody
-parallel1
-parallel2`, strings.TrimSpace(output))
+		{
+			name: "image",
+			files: map[string]string{
+				".devcontainer/devcontainer.json": fmt.Sprintf(`{
+					"name": "Test",
+					"image": %q,
+					"containerUser": "nobody",
+					"onCreateCommand": "echo create > /tmp/out",
+					"updateContentCommand": ["sh", "-c", "echo update >> /tmp/out"],
+					"postCreateCommand": "(echo -n postCreate. ; id -un) >> /tmp/out",
+					"postStartCommand": {
+						"parallel1": "echo parallel1 > /tmp/parallel1",
+						"parallel2": ["sh", "-c", "echo parallel2 > /tmp/parallel2"]
+					}
+				}`, testImageAlpine),
+			},
+			outputCmd:    "cat /tmp/out /tmp/parallel1 /tmp/parallel2",
+			expectOutput: "create\nupdate\npostCreate.nobody\nparallel1\nparallel2",
+		},
+		{
+			name: "label",
+			files: map[string]string{
+				".devcontainer/Dockerfile": fmt.Sprintf(`FROM %s
+					LABEL devcontainer.metadata='[{ \
+						"onCreateCommand": "echo create > /tmp/out", \
+						"updateContentCommand": ["sh", "-c", "echo update >> /tmp/out"], \
+						"postCreateCommand": "(echo -n postCreate. ; id -un) >> /tmp/out", \
+						"postStartCommand": { \
+							"parallel1": "echo parallel1 > /tmp/parallel1", \
+							"parallel2": ["sh", "-c", "echo parallel2 > /tmp/parallel2"] \
+						} \
+					}]'
+					USER nobody`, testImageAlpine),
+			},
+			outputCmd:    "cat /tmp/out /tmp/parallel1 /tmp/parallel2",
+			expectOutput: "create\nupdate\npostCreate.nobody\nparallel1\nparallel2",
+		},
+	} {
+		tt := tt
+		t.Run(tt.name, func(t *testing.T) {
+			srv := gittest.CreateGitServer(t, gittest.Options{
+				Files: tt.files,
+			})
+			env := []string{
+				envbuilderEnv("GIT_URL", srv.URL),
+			}
+			if _, ok := tt.files[".devcontainer/devcontainer.json"]; !ok {
+				env = append(env, envbuilderEnv("DOCKERFILE_PATH", ".devcontainer/Dockerfile"))
+			}
+			ctr, err := runEnvbuilder(t, runOpts{env: env})
+			require.NoError(t, err, "failed to run envbuilder")
+			output := execContainer(t, ctr, tt.outputCmd)
+			require.Equal(t, tt.expectOutput, strings.TrimSpace(output))
+		})
+	}
 }
 
 func TestPostStartScript(t *testing.T) {