Add support for capturing server logs

REv2's ExecuteResponse provides a field named server_logs. This is a
place where the execution environment can attach things like log files
that are generated by the remote execution environment, so that they can
be passed back to the client. I think that in addition to log files,
it's a fairly useful place for storing core dumps of actions that
crashed.

This change extends bb_worker to give every action its own server_logs
directory. We pass the path of this directory on to the runner.
bb_runner doesn't do anything with it yet, but if you end up writing
your own runner, this is where it can dump its own logs if the needs
arises.

With regards to writing core dumps into this directory, this is where it
gets a bit tricky. On Linux, you'd ideally want to set
/proc/sys/kernel/core_pattern to something like this:

    /worker/build/???/server_logs/coredump.timestamp=%t.pid=%p.executable=%e

But what should you fill in for the question marks? That part happens to
be dynamic. If you're making use of bb_runner's
symlink_temporary_directories option to symlink /tmp to the per-action
temporary directory, you're in luck. You can just use a pattern like
this:

    /tmp/../server_logs/coredump.timestamp=%t.pid=%p.executable=%e

This is guaranteed to work, because the server_logs directory always
lives right next to the per-action temporary directory. Unfortunately,
when using FUSE you're still not there. It turns out that the kernel
isn't willing to write core dumps to file systems that don't track
accurate file ownership and permissions. Fortunately, you can
proc_pattern's pipe feature to work around that:

    |/usr/bin/dd conv=excl of=/tmp/../server_logs/coredump.timestamp=%t.pid=%p.executable=%e

You do need to keep in mind such a helper process is always run in the
root namespace, and also runs as root. So instead of doing that, I'd
recommend using a command line the one below:

    |/usr/bin/nsenter -t %P -S %u -G %g -m /usr/bin/dd conv=excl of=/tmp/../server_logs/coredump.timestamp=%t.pid=%p.executable=%e

That way it runs dd inside the container of the crashing process, and
also runs as the same (non-root) user.

Author: EdSchouten

pkg/builder/build_executor.go

@@ -23,6 +23,7 @@ func NewDefaultExecuteResponse(request *remoteworker.DesiredState_Executing) *re
 				AuxiliaryMetadata: append([]*anypb.Any(nil), request.AuxiliaryMetadata...),
 			},
 		},
+		ServerLogs: map[string]*remoteexecution.LogFile{},
 	}
 }
 

pkg/builder/local_build_executor.go

@@ -27,12 +27,13 @@ import (
 
 // Filenames of objects to be created inside the build directory.
 var (
-	stdoutComponent             = path.MustNewComponent("stdout")
-	stderrComponent             = path.MustNewComponent("stderr")
-	deviceDirectoryComponent    = path.MustNewComponent("dev")
-	inputRootDirectoryComponent = path.MustNewComponent("root")
-	temporaryDirectoryComponent = path.MustNewComponent("tmp")
-	checkReadinessComponent     = path.MustNewComponent("check_readiness")
+	stdoutComponent              = path.MustNewComponent("stdout")
+	stderrComponent              = path.MustNewComponent("stderr")
+	deviceDirectoryComponent     = path.MustNewComponent("dev")
+	inputRootDirectoryComponent  = path.MustNewComponent("root")
+	serverLogsDirectoryComponent = path.MustNewComponent("server_logs")
+	temporaryDirectoryComponent  = path.MustNewComponent("tmp")
+	checkReadinessComponent      = path.MustNewComponent("check_readiness")
 )
 
 // capturingErrorLogger is an error logger that stores up to a single
@@ -243,6 +244,13 @@ func (be *localBuildExecutor) Execute(ctx context.Context, filePool re_filesyste
 		return response
 	}
 
+	if err := buildDirectory.Mkdir(serverLogsDirectoryComponent, 0o777); err != nil {
+		attachErrorToExecuteResponse(
+			response,
+			util.StatusWrap(err, "Failed to create server logs directory inside build directory"))
+		return response
+	}
+
 	executionStateUpdates <- &remoteworker.CurrentState_Executing{
 		ActionDigest: request.ActionDigest,
 		ExecutionState: &remoteworker.CurrentState_Executing_Running{
@@ -268,6 +276,7 @@ func (be *localBuildExecutor) Execute(ctx context.Context, filePool re_filesyste
 		StderrPath:           buildDirectoryPath.Append(stderrComponent).String(),
 		InputRootDirectory:   buildDirectoryPath.Append(inputRootDirectoryComponent).String(),
 		TemporaryDirectory:   buildDirectoryPath.Append(temporaryDirectoryComponent).String(),
+		ServerLogsDirectory:  buildDirectoryPath.Append(serverLogsDirectoryComponent).String(),
 	})
 	cancelTimeout()
 	<-ctxWithTimeout.Done()
@@ -317,5 +326,52 @@ func (be *localBuildExecutor) Execute(ctx context.Context, filePool re_filesyste
 		attachErrorToExecuteResponse(response, err)
 	}
 
+	// Recursively traverse the server logs directory and attach any
+	// file stored within to the ExecuteResponse.
+	serverLogsDirectoryUploader := serverLogsDirectoryUploader{
+		context:         ctx,
+		executeResponse: response,
+		digestFunction:  digestFunction,
+	}
+	serverLogsDirectoryUploader.uploadDirectory(buildDirectory, serverLogsDirectoryComponent, nil)
+
 	return response
 }
+
+type serverLogsDirectoryUploader struct {
+	context         context.Context
+	executeResponse *remoteexecution.ExecuteResponse
+	digestFunction  digest.Function
+}
+
+func (u *serverLogsDirectoryUploader) uploadDirectory(parentDirectory UploadableDirectory, dName path.Component, dPath *path.Trace) {
+	d, err := parentDirectory.EnterUploadableDirectory(dName)
+	if err != nil {
+		attachErrorToExecuteResponse(u.executeResponse, util.StatusWrapf(err, "Failed to enter server logs directory %#v", dPath.String()))
+		return
+	}
+	defer d.Close()
+
+	files, err := d.ReadDir()
+	if err != nil {
+		attachErrorToExecuteResponse(u.executeResponse, util.StatusWrapf(err, "Failed to read server logs directory %#v", dPath.String()))
+		return
+	}
+
+	for _, file := range files {
+		childName := file.Name()
+		childPath := dPath.Append(childName)
+		switch fileType := file.Type(); fileType {
+		case filesystem.FileTypeRegularFile:
+			if childDigest, err := d.UploadFile(u.context, childName, u.digestFunction); err == nil {
+				u.executeResponse.ServerLogs[childPath.String()] = &remoteexecution.LogFile{
+					Digest: childDigest.GetProto(),
+				}
+			} else {
+				attachErrorToExecuteResponse(u.executeResponse, util.StatusWrapf(err, "Failed to store server log %#v", childPath.String()))
+			}
+		case filesystem.FileTypeDirectory:
+			u.uploadDirectory(d, childName, childPath)
+		}
+	}
+}

pkg/builder/local_build_executor_test.go

@@ -374,6 +374,7 @@ func TestLocalBuildExecutorOutputSymlinkReadingFailure(t *testing.T) {
 		monitor,
 	).Return(nil)
 	buildDirectory.EXPECT().Mkdir(path.MustNewComponent("tmp"), os.FileMode(0o777))
+	buildDirectory.EXPECT().Mkdir(path.MustNewComponent("server_logs"), os.FileMode(0o777))
 	runner := mock.NewMockRunnerClient(ctrl)
 	runner.EXPECT().Run(gomock.Any(), &runner_pb.RunRequest{
 		Arguments:            []string{"touch", "foo"},
@@ -383,6 +384,7 @@ func TestLocalBuildExecutorOutputSymlinkReadingFailure(t *testing.T) {
 		StderrPath:           "stderr",
 		InputRootDirectory:   "root",
 		TemporaryDirectory:   "tmp",
+		ServerLogsDirectory:  "server_logs",
 	}).Return(&runner_pb.RunResponse{
 		ExitCode: 0,
 	}, nil)
@@ -395,6 +397,10 @@ func TestLocalBuildExecutorOutputSymlinkReadingFailure(t *testing.T) {
 	fooDirectory.EXPECT().Readlink(path.MustNewComponent("bar")).Return("", status.Error(codes.Internal, "Cosmic rays caused interference"))
 	fooDirectory.EXPECT().Close()
 	inputRootDirectory.EXPECT().Close()
+	serverLogsDirectory := mock.NewMockUploadableDirectory(ctrl)
+	buildDirectory.EXPECT().EnterUploadableDirectory(path.MustNewComponent("server_logs")).Return(serverLogsDirectory, nil)
+	serverLogsDirectory.EXPECT().ReadDir()
+	serverLogsDirectory.EXPECT().Close()
 	buildDirectory.EXPECT().Close()
 	clock := mock.NewMockClock(ctrl)
 	clock.EXPECT().NewContextWithTimeout(gomock.Any(), time.Hour).DoAndReturn(func(parent context.Context, timeout time.Duration) (context.Context, context.CancelFunc) {
@@ -573,6 +579,7 @@ func TestLocalBuildExecutorSuccess(t *testing.T) {
 		filesystem.NewDeviceNumberFromMajorMinor(1, 3))
 	inputRootDevDirectory.EXPECT().Close()
 	buildDirectory.EXPECT().Mkdir(path.MustNewComponent("tmp"), os.FileMode(0o777))
+	buildDirectory.EXPECT().Mkdir(path.MustNewComponent("server_logs"), os.FileMode(0o777))
 	resourceUsage, err := anypb.New(&emptypb.Empty{})
 	require.NoError(t, err)
 	runner := mock.NewMockRunnerClient(ctrl)
@@ -593,16 +600,21 @@ func TestLocalBuildExecutorSuccess(t *testing.T) {
 			"PWD":                               "/proc/self/cwd",
 			"TEST_VAR":                          "123",
 		},
-		WorkingDirectory:   "",
-		StdoutPath:         "0000000000000000/stdout",
-		StderrPath:         "0000000000000000/stderr",
-		InputRootDirectory: "0000000000000000/root",
-		TemporaryDirectory: "0000000000000000/tmp",
+		WorkingDirectory:    "",
+		StdoutPath:          "0000000000000000/stdout",
+		StderrPath:          "0000000000000000/stderr",
+		InputRootDirectory:  "0000000000000000/root",
+		TemporaryDirectory:  "0000000000000000/tmp",
+		ServerLogsDirectory: "0000000000000000/server_logs",
 	}).Return(&runner_pb.RunResponse{
 		ExitCode:      0,
 		ResourceUsage: []*anypb.Any{resourceUsage},
 	}, nil)
 	inputRootDirectory.EXPECT().Close()
+	serverLogsDirectory := mock.NewMockUploadableDirectory(ctrl)
+	buildDirectory.EXPECT().EnterUploadableDirectory(path.MustNewComponent("server_logs")).Return(serverLogsDirectory, nil)
+	serverLogsDirectory.EXPECT().ReadDir()
+	serverLogsDirectory.EXPECT().Close()
 	buildDirectory.EXPECT().Close()
 	clock := mock.NewMockClock(ctrl)
 	clock.EXPECT().NewContextWithTimeout(gomock.Any(), time.Hour).DoAndReturn(func(parent context.Context, timeout time.Duration) (context.Context, context.CancelFunc) {
@@ -764,6 +776,7 @@ func TestLocalBuildExecutorInputRootIOFailureDuringExecution(t *testing.T) {
 		return nil
 	})
 	buildDirectory.EXPECT().Mkdir(path.MustNewComponent("tmp"), os.FileMode(0o777))
+	buildDirectory.EXPECT().Mkdir(path.MustNewComponent("server_logs"), os.FileMode(0o777))
 
 	// Let an I/O error in the input root trigger during the build.
 	// The build should be canceled immediately. The error should be
@@ -777,12 +790,17 @@ func TestLocalBuildExecutorInputRootIOFailureDuringExecution(t *testing.T) {
 		StderrPath:           "stderr",
 		InputRootDirectory:   "root",
 		TemporaryDirectory:   "tmp",
+		ServerLogsDirectory:  "server_logs",
 	}).DoAndReturn(func(ctx context.Context, request *runner_pb.RunRequest, opts ...grpc.CallOption) (*runner_pb.RunResponse, error) {
 		errorLogger.Log(status.Error(codes.FailedPrecondition, "Blob not found"))
 		<-ctx.Done()
 		return nil, util.StatusFromContext(ctx)
 	})
 	inputRootDirectory.EXPECT().Close()
+	serverLogsDirectory := mock.NewMockUploadableDirectory(ctrl)
+	buildDirectory.EXPECT().EnterUploadableDirectory(path.MustNewComponent("server_logs")).Return(serverLogsDirectory, nil)
+	serverLogsDirectory.EXPECT().ReadDir()
+	serverLogsDirectory.EXPECT().Close()
 	buildDirectory.EXPECT().Close()
 	clock := mock.NewMockClock(ctrl)
 	clock.EXPECT().NewContextWithTimeout(gomock.Any(), 15*time.Minute).DoAndReturn(func(parent context.Context, timeout time.Duration) (context.Context, context.CancelFunc) {
@@ -871,6 +889,7 @@ func TestLocalBuildExecutorTimeoutDuringExecution(t *testing.T) {
 		monitor,
 	).Return(nil)
 	buildDirectory.EXPECT().Mkdir(path.MustNewComponent("tmp"), os.FileMode(0o777))
+	buildDirectory.EXPECT().Mkdir(path.MustNewComponent("server_logs"), os.FileMode(0o777))
 
 	// Simulate a timeout by running the command with a timeout of
 	// zero seconds. This should cause an immediate build failure.
@@ -883,11 +902,24 @@ func TestLocalBuildExecutorTimeoutDuringExecution(t *testing.T) {
 		StderrPath:           "stderr",
 		InputRootDirectory:   "root",
 		TemporaryDirectory:   "tmp",
+		ServerLogsDirectory:  "server_logs",
 	}).DoAndReturn(func(ctx context.Context, request *runner_pb.RunRequest, opts ...grpc.CallOption) (*runner_pb.RunResponse, error) {
 		<-ctx.Done()
 		return nil, util.StatusFromContext(ctx)
 	})
 	inputRootDirectory.EXPECT().Close()
+
+	// Let the server logs directory contain a log file. It should
+	// get attached to the ExecuteResponse.
+	serverLogsDirectory := mock.NewMockUploadableDirectory(ctrl)
+	buildDirectory.EXPECT().EnterUploadableDirectory(path.MustNewComponent("server_logs")).Return(serverLogsDirectory, nil)
+	serverLogsDirectory.EXPECT().ReadDir().Return([]filesystem.FileInfo{
+		filesystem.NewFileInfo(path.MustNewComponent("kernel_log"), filesystem.FileTypeRegularFile, false),
+	}, nil)
+	serverLogsDirectory.EXPECT().UploadFile(ctx, path.MustNewComponent("kernel_log"), gomock.Any()).Return(
+		digest.MustNewDigest("ubuntu1804", remoteexecution.DigestFunction_SHA256, "53855840865bc43fa60c2e25383165017cfc3c2243541f8e6c648f5fbd374eb5", 1200),
+		nil)
+	serverLogsDirectory.EXPECT().Close()
 	buildDirectory.EXPECT().Close()
 	clock := mock.NewMockClock(ctrl)
 	clock.EXPECT().NewContextWithTimeout(gomock.Any(), time.Hour).DoAndReturn(func(parent context.Context, timeout time.Duration) (context.Context, context.CancelFunc) {
@@ -931,6 +963,14 @@ func TestLocalBuildExecutorTimeoutDuringExecution(t *testing.T) {
 			},
 			ExecutionMetadata: &remoteexecution.ExecutedActionMetadata{},
 		},
+		ServerLogs: map[string]*remoteexecution.LogFile{
+			"kernel_log": {
+				Digest: &remoteexecution.Digest{
+					Hash:      "53855840865bc43fa60c2e25383165017cfc3c2243541f8e6c648f5fbd374eb5",
+					SizeBytes: 1200,
+				},
+			},
+		},
 		Status: status.New(codes.DeadlineExceeded, "Failed to run command: context deadline exceeded").Proto(),
 	}, executeResponse)
 }

pkg/proto/runner/runner.pb.go

@@ -54,6 +54,10 @@ message RunRequest {
   // Path of a scratch space directory that may be used by the build
   // action, relative to the build directory.
   string temporary_directory = 7;
+
+  // Path where files may be stored that are attached to the REv2
+  // ExecuteResponse in the form of server logs.
+  string server_logs_directory = 8;
 }
 
 message RunResponse {