disable strace debug logging in worker, add feature flag to enable separate logging in analysis image

cmd/analyze/main.go

@@ -37,6 +37,7 @@ var (
 	offline             = flag.Bool("offline", false, "disables sandbox network access")
 	customSandbox       = flag.String("sandbox-image", "", "override default dynamic analysis sandbox with custom image")
 	customAnalysisCmd   = flag.String("analysis-command", "", "override default dynamic analysis script path (use with custom sandbox image)")
+	straceLogsDir       = flag.String("strace-logs-dir", "", "specify directory in container to write strace logs (for -feature 'StraceDebugLogging')")
 	listModes           = flag.Bool("list-modes", false, "prints out a list of available analysis modes")
 	features            = flag.String("features", "", "override features that are enabled/disabled by default")
 	listFeatures        = flag.Bool("list-features", false, "list available features that can be toggled")
@@ -126,6 +127,10 @@ func dynamicAnalysis(ctx context.Context, pkg *pkgmanager.Pkg, resultStores *wor
 		sbOpts = append(sbOpts, sandbox.Image(*customSandbox))
 	}
 
+	if featureflags.StraceDebugLogging.Enabled() && *straceLogsDir != "" {
+		ctx = context.WithValue(ctx, log.StraceDebugLogDirKey, *straceLogsDir)
+	}
+
 	result, err := worker.RunDynamicAnalysis(ctx, pkg, sbOpts, *customAnalysisCmd)
 	if err != nil {
 		slog.ErrorContext(ctx, "Dynamic analysis aborted (run error)", "error", err)

internal/dynamicanalysis/analysis.go

@@ -64,7 +64,7 @@ func Run(ctx context.Context, sb sandbox.Sandbox, command string, args []string,
 	}
 	defer l.Close()
 
-	straceResult, err := strace.Parse(l, straceLogger)
+	straceResult, err := strace.Parse(ctx, l, straceLogger)
 	if err != nil {
 		return resultError, fmt.Errorf("strace parsing failed (%w)", err)
 	}

internal/featureflags/features.go

@@ -17,4 +17,10 @@ var (
 	// which may uncover extra malicious behaviour. The names of executed functions,
 	// methods and classes are logged to a file.
 	CodeExecution = new("CodeExecution", false)
+
+	// StraceDebugLogging enables verbose logging of strace parsing during dynamic analysis.
+	// This feature can only be used in the analysis image, and if enabled, the -strace-logs-dir
+	// flag must also be set. When enabled, the log files are then accessible via an explicit
+	// docker mount or copy of the specified directory from the container to the host filesystem.
+	StraceDebugLogging = new("StraceDebugLogging", false)
 )

internal/log/log.go

@@ -29,6 +29,10 @@ func (e LoggingEnv) String() string {
 const (
 	LoggingEnvDev  LoggingEnv = "dev"
 	LoggingEnvProd LoggingEnv = "prod"
+
+	// StraceDebugLogDirKey is a context object key used to store the path to the
+	// strace debug log, if strace debug logging is enabled
+	StraceDebugLogDirKey = "strace_log_dir"
 )
 
 var (

internal/strace/strace.go

@@ -2,6 +2,7 @@ package strace
 
 import (
 	"bufio"
+	"context"
 	"crypto/sha256"
 	"encoding/hex"
 	"encoding/json"
@@ -154,7 +155,7 @@ func (r *Result) recordFileAccess(file string, read, write, del bool) {
 	r.files[file].Delete = r.files[file].Delete || del
 }
 
-func (r *Result) recordFileWrite(file string, writeBuffer []byte, bytesWritten int64, logger *slog.Logger) error {
+func (r *Result) recordFileWrite(file string, writeBuffer []byte, bytesWritten int64) error {
 	r.recordFileAccess(file, false, true, false)
 	if !featureflags.WriteFileContents.Enabled() {
 		// Abort writing file contents when feature is disabled.
@@ -220,7 +221,7 @@ func (r *Result) parseEnterSyscall(syscall, args string, logger *slog.Logger) er
 			writeBuffer = args[firstQuoteIndex+1 : lastQuoteIndex]
 		}
 		logger.Debug("write", "path", path, "size", bytesWritten)
-		return r.recordFileWrite(path, []byte(writeBuffer), bytesWritten, logger)
+		return r.recordFileWrite(path, []byte(writeBuffer), bytesWritten)
 	}
 	return nil
 }
@@ -323,9 +324,9 @@ func (r *Result) parseExitSyscall(syscall, args string, logger *slog.Logger) err
 	return nil
 }
 
-// Parse reads an strace and collects the files, sockets and commands that were
-// accessed.
-func Parse(r io.Reader, logger *slog.Logger) (*Result, error) {
+// Parse reads the output from strace and collects the files, sockets and commands that
+// were accessed. debugLogger can be used to log verbose information about strace parsing.
+func Parse(ctx context.Context, r io.Reader, debugLogger *slog.Logger) (*Result, error) {
 	result := &Result{
 		files:            make(map[string]*FileInfo),
 		sockets:          make(map[string]*SocketInfo),
@@ -345,18 +346,18 @@ func Parse(r io.Reader, logger *slog.Logger) (*Result, error) {
 		if match != nil {
 			if match[2] == "E" {
 				// Analyze entry events.
-				if err := result.parseEnterSyscall(match[3], match[4], logger); errors.Is(err, ErrParseFailure) {
+				if err := result.parseEnterSyscall(match[3], match[4], debugLogger); errors.Is(err, ErrParseFailure) {
 					// Log parsing errors and continue.
-					logger.Warn("Failed to parse entry syscall", "error", err)
+					slog.WarnContext(ctx, "Failed to parse entry syscall", "error", err)
 				} else if err != nil {
 					return nil, err
 				}
 			}
 			if match[2] == "X" {
 				// Analyze exit events.
-				if err := result.parseExitSyscall(match[3], match[4], logger); errors.Is(err, ErrParseFailure) {
+				if err := result.parseExitSyscall(match[3], match[4], debugLogger); errors.Is(err, ErrParseFailure) {
 					// Log parsing errors and continue.
-					logger.Warn("Failed to parse exit syscall", "error", err)
+					slog.WarnContext(ctx, "Failed to parse exit syscall", "error", err)
 				} else if err != nil {
 					return nil, err
 				}

internal/strace/strace_test.go

@@ -1,6 +1,7 @@
 package strace_test
 
 import (
+	"context"
 	"fmt"
 	"io"
 	"log/slog"
@@ -12,12 +13,12 @@ import (
 	"github.com/ossf/package-analysis/internal/utils"
 )
 
-var nopLogger = slog.New(slog.NewTextHandler(io.Discard, &slog.HandlerOptions{}))
+var nopLogger = slog.New(slog.NewTextHandler(io.Discard, nil))
 
 func TestIgnoreEntryLogs(t *testing.T) {
 	input := "I1203 05:29:21.585712     173 strace.go:625] [   2] python3 E creat(0x7f015d7865d0 /tmp/abctest, 0o600)"
 	r := strings.NewReader(input)
-	res, err := strace.Parse(r, nopLogger)
+	res, err := strace.Parse(context.Background(), r, nopLogger)
 	if err != nil || res == nil {
 		t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}
@@ -36,7 +37,7 @@ func TestParseFileReadThenCreate(t *testing.T) {
 	}
 
 	r := strings.NewReader(input)
-	res, err := strace.Parse(r, nopLogger)
+	res, err := strace.Parse(context.Background(), r, nopLogger)
 	if err != nil || res == nil {
 		t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}
@@ -65,7 +66,7 @@ func TestParseFileWriteMultipleWritesToSameFile(t *testing.T) {
 		WriteInfo: writeInfoWantArray}
 
 	r := strings.NewReader(input)
-	res, err := strace.Parse(r, nopLogger)
+	res, err := strace.Parse(context.Background(), r, nopLogger)
 	if err != nil || res == nil {
 		t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}
@@ -106,7 +107,7 @@ func TestParseFileWritesToDifferentFiles(t *testing.T) {
 	want := []strace.FileInfo{firstFileWant, secondFileWant}
 
 	r := strings.NewReader(input)
-	res, err := strace.Parse(r, nopLogger)
+	res, err := strace.Parse(context.Background(), r, nopLogger)
 	if err != nil || res == nil {
 		t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}
@@ -134,7 +135,7 @@ func TestParseFileWriteWithZeroBytesWritten(t *testing.T) {
 	}
 
 	r := strings.NewReader(input)
-	res, err := strace.Parse(r, nopLogger)
+	res, err := strace.Parse(context.Background(), r, nopLogger)
 	if err != nil || res == nil {
 		t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}
@@ -314,7 +315,7 @@ func TestParseFilesOneEntry(t *testing.T) {
 	for _, test := range tests {
 		t.Run(test.name, func(t *testing.T) {
 			r := strings.NewReader(test.input)
-			res, err := strace.Parse(r, nopLogger)
+			res, err := strace.Parse(context.Background(), r, nopLogger)
 			if err != nil || res == nil {
 				t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 			}
@@ -331,7 +332,7 @@ func TestParseIgnoredSockets(t *testing.T) {
 		"I1206 02:02:36.989375     205 strace.go:622] [   2] gem X bind(0x5 socket:[1], 0x7f414ed92cf8 {Family: AF_NETLINK, PortID: 0, Groups: 0}, 0xc) = 0x0 (16.276µs)\n" +
 		"I1206 02:02:36.990646     205 strace.go:622] [   2] gem X connect(0x5 socket:[2], 0x7f414ed93080 {Family: AF_UNSPEC, family addr format unknown}, 0x10) = 0x0 (8.598µs)\n"
 	r := strings.NewReader(input)
-	res, err := strace.Parse(r, nopLogger)
+	res, err := strace.Parse(context.Background(), r, nopLogger)
 	if err != nil || res == nil {
 		t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}
@@ -408,7 +409,7 @@ func TestParseSocketsOneEntry(t *testing.T) {
 	for _, test := range tests {
 		t.Run(test.name, func(t *testing.T) {
 			r := strings.NewReader(test.input)
-			res, err := strace.Parse(r, nopLogger)
+			res, err := strace.Parse(context.Background(), r, nopLogger)
 			if err != nil || res == nil {
 				t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 			}
@@ -426,7 +427,7 @@ func TestReallyLongLogLine(t *testing.T) {
 	input := fmt.Sprintf(inputTmpl, strings.Repeat(part, 1000))
 
 	r := strings.NewReader(input)
-	res, err := strace.Parse(r, nopLogger)
+	res, err := strace.Parse(context.Background(), r, nopLogger)
 	if err != nil || res == nil {
 		t.Fatalf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}

internal/worker/rundynamic.go

@@ -2,9 +2,14 @@ package worker
 
 import (
 	"context"
+	"fmt"
+	"io"
 	"log/slog"
+	"os"
+	"path/filepath"
 	"runtime"
 	"strconv"
+	"strings"
 	"time"
 
 	"github.com/ossf/package-analysis/internal/analysis"
@@ -148,11 +153,63 @@ func RunDynamicAnalysis(ctx context.Context, pkg *pkgmanager.Pkg, sbOpts []sandb
 	return result, nil
 }
 
+// openStraceDebugLogFile returns the file to be used for debug logging of strace parsing during a
+// dynamic analysis phase, or nil if logging should be disabled or an error occurred while opening it.
+// The file is created with the given filename. It should be closed by the caller.
+// The directory path (within the analysis container) is configured via setting a (string) value
+// for the log.StraceDebugLogDirKey key on the context object passed to this function. If there
+// is no directory configured, logging will be disabled
+func openStraceDebugLogFile(ctx context.Context, name string) *os.File {
+	if !featureflags.StraceDebugLogging.Enabled() {
+		return nil
+	}
+
+	var logDir string
+	if v := ctx.Value(log.StraceDebugLogDirKey); v == nil {
+		slog.WarnContext(ctx, "StraceDebugLogging enabled but log dir not set")
+		return nil
+	} else if dirPath, ok := v.(string); !ok {
+		slog.WarnContext(ctx, "non-string value for log.StraceDebugLogDirKey", "value", v)
+		return nil
+	} else {
+		logDir = dirPath
+	}
+
+	if err := os.MkdirAll(logDir, 0o777); err != nil {
+		slog.WarnContext(ctx, "could not create directory for strace debug log file", "path", logDir, "error", err)
+	}
+
+	logPath := filepath.Join(logDir, name)
+	if logFile, err := os.Create(logPath); err != nil {
+		slog.WarnContext(ctx, "could not create strace debug log file", "path", logPath, "error", err)
+		return nil
+	} else {
+		return logFile
+	}
+}
+
+func straceDebugLogFilename(pkg *pkgmanager.Pkg, phase analysisrun.DynamicPhase) string {
+	filename := fmt.Sprintf("strace-%s-%s-%s-%s.log", pkg.EcosystemName(), pkg.Name(), pkg.Version(), phase)
+	// protect against e.g. a package name that contains a slash
+	return strings.ReplaceAll(filename, string(os.PathSeparator), "-")
+}
+
 func runDynamicAnalysisPhase(ctx context.Context, pkg *pkgmanager.Pkg, sb sandbox.Sandbox, analysisCmd string, phase analysisrun.DynamicPhase, result *DynamicAnalysisResult) error {
 	phaseCtx := log.ContextWithAttrs(ctx, log.Label("phase", string(phase)))
 	startTime := time.Now()
 	args := dynamicanalysis.MakeAnalysisArgs(pkg, phase)
-	phaseResult, err := dynamicanalysis.Run(ctx, sb, analysisCmd, args, log.LoggerWithContext(slog.Default(), ctx))
+
+	straceLogger := slog.New(slog.NewTextHandler(io.Discard, nil)) // default is nop logger
+	if logFile := openStraceDebugLogFile(phaseCtx, straceDebugLogFilename(pkg, phase)); logFile != nil {
+		slog.InfoContext(phaseCtx, "strace debug logging enabled")
+		defer logFile.Close()
+
+		enableDebug := &slog.HandlerOptions{Level: slog.LevelDebug}
+		straceLogger = slog.New(log.NewContextLogHandler(slog.NewTextHandler(logFile, enableDebug)))
+		straceLogger.InfoContext(phaseCtx, "running dynamic analysis")
+	}
+
+	phaseResult, err := dynamicanalysis.Run(phaseCtx, sb, analysisCmd, args, straceLogger)
 	result.LastRunPhase = phase
 	runDuration := time.Since(startTime)
 	slog.InfoContext(phaseCtx, "Dynamic analysis phase finished",

scripts/run_analysis.sh

@@ -5,6 +5,7 @@ STATIC_RESULTS_DIR=${STATIC_RESULTS_DIR:-"/tmp/staticResults"}
 FILE_WRITE_RESULTS_DIR=${FILE_WRITE_RESULTS_DIR:-"/tmp/writeResults"}
 ANALYZED_PACKAGES_DIR=${ANALYZED_PACKAGES_DIR:-"/tmp/analyzedPackages"}
 LOGS_DIR=${LOGS_DIR:-"/tmp/dockertmp"}
+STRACE_LOGS_DIR=${STRACE_LOGS_DIR:-"/tmp/straceLogs"}
 
 # for pretty printing
 LINE="-----------------------------------------"
@@ -45,6 +46,7 @@ function print_results_dirs {
 	echo "File write results:       $FILE_WRITE_RESULTS_DIR"
 	echo "Analyzed package saved:   $ANALYZED_PACKAGES_DIR"
 	echo "Debug logs:               $LOGS_DIR"
+	echo "Strace logs:              $STRACE_LOGS_DIR"
 }
 
 
@@ -81,12 +83,13 @@ while [[ $i -lt $# ]]; do
 			HELP=1
 			;;
 		"-local")
+			# need to create a mount to pass the package archive to the docker image
 			LOCAL=1
 			i=$((i+1))
 			# -m preserves invalid/non-existent paths (which will be detected below)
 			PKG_PATH=$(realpath -m "${args[$i]}")
 			if [[ -z "$PKG_PATH" ]]; then
-				echo "--local specified but no package path given"
+				echo "-local specified but no package path given"
 				exit 255
 			fi
 			PKG_FILE=$(basename "$PKG_PATH")
@@ -150,11 +153,11 @@ elif is_mount_type overlay /var/lib; then
 fi
 
 
-DOCKER_MOUNTS=("-v" "$CONTAINER_MOUNT_DIR:/var/lib/containers" "-v" "$RESULTS_DIR:/results" "-v" "$STATIC_RESULTS_DIR:/staticResults" "-v" "$FILE_WRITE_RESULTS_DIR:/writeResults" "-v" "$LOGS_DIR:/tmp" "-v" "$ANALYZED_PACKAGES_DIR:/analyzedPackages")
+DOCKER_MOUNTS=("-v" "$CONTAINER_MOUNT_DIR:/var/lib/containers" "-v" "$RESULTS_DIR:/results" "-v" "$STATIC_RESULTS_DIR:/staticResults" "-v" "$FILE_WRITE_RESULTS_DIR:/writeResults" "-v" "$LOGS_DIR:/tmp" "-v" "$ANALYZED_PACKAGES_DIR:/analyzedPackages" "-v" "$STRACE_LOGS_DIR:/straceLogs")
 
 ANALYSIS_IMAGE=gcr.io/ossf-malware-analysis/analysis
 
-ANALYSIS_ARGS=("analyze" "-upload" "file:///results/" "-upload-file-write-info" "file:///writeResults/" "-upload-static" "file:///staticResults/" "-upload-analyzed-pkg" "file:///analyzedPackages/")
+ANALYSIS_ARGS=("analyze" "-upload" "file:///results/" "-upload-file-write-info" "file:///writeResults/" "-upload-static" "file:///staticResults/" "-upload-analyzed-pkg" "file:///analyzedPackages/" -strace-logs-dir "/straceLogs")
 
 # Add the remaining command line arguments
 ANALYSIS_ARGS=("${ANALYSIS_ARGS[@]}" "${args[@]}")
@@ -222,6 +225,7 @@ mkdir -p "$STATIC_RESULTS_DIR"
 mkdir -p "$FILE_WRITE_RESULTS_DIR"
 mkdir -p "$ANALYZED_PACKAGES_DIR"
 mkdir -p "$LOGS_DIR"
+mkdir -p "$STRACE_LOGS_DIR"
 
 docker "${DOCKER_OPTS[@]}" "${DOCKER_MOUNTS[@]}" "$ANALYSIS_IMAGE" "${ANALYSIS_ARGS[@]}"
 
@@ -246,6 +250,7 @@ echo $LINE
 		rmdir --ignore-fail-on-non-empty "$FILE_WRITE_RESULTS_DIR"
 		rmdir --ignore-fail-on-non-empty "$ANALYZED_PACKAGES_DIR"
 		rmdir --ignore-fail-on-non-empty "$LOGS_DIR"
+		rmdir --ignore-fail-on-non-empty "$STRACE_LOGS_DIR"
 	fi
 
 echo $LINE