Repository: ossf/package-analysis (language: python)

Issue:
Log strace raw data to a separate file instead of stdout
Currently, `cmd/analyze/main.go` prints out every single parsed strace line, which is very noisy and makes it hard to debug analysis errors in console output. It would be more useful to have this data written to a separate file, or supressed if desired. 


Discussion / hints:

Fix patch:
diff --git a/cmd/scheduler/main.go b/cmd/scheduler/main.go
index 0c3ac5a8..cc8d4bcf 100644
--- a/cmd/scheduler/main.go
+++ b/cmd/scheduler/main.go
@@ -60,7 +60,7 @@ var supportedPkgManagers = map[string]*ManagerConfig{
 func main() {
 	subscriptionURL := os.Getenv("OSSMALWARE_SUBSCRIPTION_URL")
 	topicURL := os.Getenv("OSSMALWARE_WORKER_TOPIC")
-	logger := log.Initialize(os.Getenv("LOGGER_ENV"))
+	logger := log.Initialize(os.Getenv("LOGGER_ENV")).Desugar()
 
 	err := listenLoop(logger, subscriptionURL, topicURL)
 	if err != nil {
diff --git a/cmd/worker/main.go b/cmd/worker/main.go
index a8557369..b3ca80f4 100644
--- a/cmd/worker/main.go
+++ b/cmd/worker/main.go
@@ -311,6 +311,6 @@ func main() {
 
 	err := messageLoop(ctx, subURL, packagesBucket, notificationTopicURL, imageSpec, &resultStores)
 	if err != nil {
-		log.Error("Error encountered", "error", err)
+		logger.Errorw("Error encountered", "error", err)
 	}
 }
diff --git a/internal/dynamicanalysis/analysis.go b/internal/dynamicanalysis/analysis.go
index 65e6938d..2a20238f 100644
--- a/internal/dynamicanalysis/analysis.go
+++ b/internal/dynamicanalysis/analysis.go
@@ -3,6 +3,8 @@ package dynamicanalysis
 import (
 	"fmt"
 
+	"go.uber.org/zap"
+
 	"github.com/ossf/package-analysis/internal/analysis"
 	"github.com/ossf/package-analysis/internal/dnsanalyzer"
 	"github.com/ossf/package-analysis/internal/log"
@@ -30,7 +32,7 @@ var resultError = &Result{
 	},
 }
 
-func Run(sb sandbox.Sandbox, command string, args []string) (*Result, error) {
+func Run(sb sandbox.Sandbox, command string, args []string, straceLogger *zap.SugaredLogger) (*Result, error) {
 	log.Info("Running dynamic analysis",
 		"args", args)
 
@@ -63,7 +65,7 @@ func Run(sb sandbox.Sandbox, command string, args []string) (*Result, error) {
 	}
 	defer l.Close()
 
-	straceResult, err := strace.Parse(l)
+	straceResult, err := strace.Parse(l, straceLogger)
 	if err != nil {
 		return resultError, fmt.Errorf("strace parsing failed (%w)", err)
 	}
diff --git a/internal/log/log.go b/internal/log/log.go
index 816cc8a5..5aa82d8f 100644
--- a/internal/log/log.go
+++ b/internal/log/log.go
@@ -46,17 +46,23 @@ const (
 )
 
 var (
+	// Default logger is the legacy global logger for package analysis
+	// Deprecated: do not use global logger
 	defaultLogger     *zap.SugaredLogger
 	defaultLoggingEnv LoggingEnv = LoggingEnvDev
 )
 
+func GetDefaultLogger() *zap.SugaredLogger {
+	return defaultLogger
+}
+
 // Initialize the logger for logging.
 //
 // Passing in "true" will use Zap's default production configuration, while
 // "false" will use the default development configuration.
 //
 // Note: this method MUST be called before any other method in this package.
-func Initialize(env string) *zap.Logger {
+func Initialize(env string) *zap.SugaredLogger {
 	var err error
 	var logger *zap.Logger
 	switch strings.ToLower(env) {
@@ -79,7 +85,7 @@ func Initialize(env string) *zap.Logger {
 	zap.RedirectStdLog(logger)
 	logger = logger.WithOptions(zap.AddCallerSkip(1))
 	defaultLogger = logger.Sugar() // Set defaultLogger to provide legacy support
-	return logger
+	return defaultLogger
 }
 
 func checkInit() {
diff --git a/internal/strace/strace.go b/internal/strace/strace.go
index 56582ce8..f4a7f93c 100644
--- a/internal/strace/strace.go
+++ b/internal/strace/strace.go
@@ -14,6 +14,8 @@ import (
 	"strings"
 	"unicode"
 
+	"go.uber.org/zap"
+
 	"github.com/ossf/package-analysis/internal/featureflags"
 	"github.com/ossf/package-analysis/internal/log"
 	"github.com/ossf/package-analysis/internal/utils"
@@ -192,7 +194,7 @@ func (r *Result) recordCommand(cmd, env []string) {
 	}
 }
 
-func (r *Result) parseEnterSyscall(syscall, args string) error {
+func (r *Result) parseEnterSyscall(syscall, args string, logger *zap.SugaredLogger) error {
 	switch syscall {
 	case "write":
 		// The index of the start of bytes written. Bytes written is expected to be in hex.
@@ -208,18 +210,20 @@ func (r *Result) parseEnterSyscall(syscall, args string) error {
 		}
 		writeBuffer := ""
 		match := writePattern.FindStringSubmatch(args)
+		path := match[1]
 		firstQuoteIndex := strings.Index(args, "\"")
 		lastQuoteIndex := strings.LastIndex(args, "\"")
 		if firstQuoteIndex != -1 && lastQuoteIndex != -1 && lastQuoteIndex > firstQuoteIndex {
 			// Save the contents between the first and last quote.
 			writeBuffer = args[firstQuoteIndex+1 : lastQuoteIndex]
 		}
-		r.recordFileWrite(match[1], []byte(writeBuffer), bytesWritten)
+		logger.Debugw("write", "path", path, "size", bytesWritten)
+		r.recordFileWrite(path, []byte(writeBuffer), bytesWritten)
 	}
 	return nil
 }
 
-func (r *Result) parseExitSyscall(syscall, args string) error {
+func (r *Result) parseExitSyscall(syscall, args string, logger *zap.SugaredLogger) error {
 	switch syscall {
 	case "creat":
 		match := creatPattern.FindStringSubmatch(args)
@@ -227,21 +231,19 @@ func (r *Result) parseExitSyscall(syscall, args string) error {
 			return fmt.Errorf("failed to parse create args: %s", args)
 		}
 
-		log.Debug("creat",
-			"path", match[1])
-		r.recordFileAccess(match[1], false, true, false)
+		path := match[1]
+		logger.Debugw("creat", "path", path)
+		r.recordFileAccess(path, false, true, false)
 	case "open":
 		match := openPattern.FindStringSubmatch(args)
 		if match == nil {
 			return fmt.Errorf("failed to parse open args: %s", args)
 		}
 
+		path := match[1]
 		read, write := parseOpenFlags(match[2])
-		log.Debug("open",
-			"path", match[1],
-			"read", read,
-			"write", write)
-		r.recordFileAccess(match[1], read, write, false)
+		logger.Debugw("open", "path", path, "read", read, "write", write)
+		r.recordFileAccess(path, read, write, false)
 	case "openat":
 		match := openatPattern.FindStringSubmatch(args)
 		if match == nil {
@@ -250,18 +252,15 @@ func (r *Result) parseExitSyscall(syscall, args string) error {
 
 		path := joinPaths(match[1], match[2])
 		read, write := parseOpenFlags(match[3])
-		log.Debug("openat",
-			"path", path,
-			"read", read,
-			"write", write)
+		logger.Debugw("openat", "path", path, "read", read, "write", write)
 		r.recordFileAccess(path, read, write, false)
 	case "execve":
 		match := execvePattern.FindStringSubmatch(args)
 		if match == nil {
 			return fmt.Errorf("failed to parse execve args: %s", args)
 		}
-		log.Debug("execve",
-			"cmdAndEnv", match[1])
+
+		logger.Debugw("execve", "cmdAndEnv", match[1])
 		cmd, env, err := parseCmdAndEnv(match[1])
 		if err != nil {
 			return err
@@ -284,26 +283,23 @@ func (r *Result) parseExitSyscall(syscall, args string) error {
 		if err != nil {
 			return err
 		}
-		log.Debug("socket",
-			"address", address,
-			"port", port)
+		logger.Debugw("socket", "address", address, "port", port)
 		r.recordSocket(address, port)
 	case "stat", "fstat", "lstat":
 		match := statPattern.FindStringSubmatch(args)
 		if match == nil {
 			return fmt.Errorf("failed to parse stat args: %s", args)
 		}
-		log.Debug("stat",
-			"path", match[1])
-		r.recordFileAccess(match[1], true, false, false)
+		path := match[1]
+		logger.Debugw("stat", "path", path)
+		r.recordFileAccess(path, true, false, false)
 	case "newfstatat":
 		match := newfstatatPattern.FindStringSubmatch(args)
 		if match == nil {
 			return fmt.Errorf("failed to parse newfstatat args: %s", args)
 		}
 		path := joinPaths(match[1], match[2])
-		log.Debug("newfstatat",
-			"path", path)
+		logger.Debugw("newfstatat", "path", path)
 		r.recordFileAccess(path, true, false, false)
 	case "unlink":
 		match := unlinkPatten.FindStringSubmatch(args)
@@ -311,8 +307,7 @@ func (r *Result) parseExitSyscall(syscall, args string) error {
 			return fmt.Errorf("failed to parse unlink args: %s", args)
 		}
 		path := match[1]
-		log.Debug("unlink",
-			"path", path)
+		logger.Infow("unlink", "path", path)
 		r.recordFileAccess(path, false, false, true)
 	case "unlinkat":
 		match := unlinkatPattern.FindStringSubmatch(args)
@@ -320,8 +315,7 @@ func (r *Result) parseExitSyscall(syscall, args string) error {
 			return fmt.Errorf("failed to parse unlinkat args: %s", args)
 		}
 		path := joinPaths(match[1], match[2])
-		log.Debug("unlinkat",
-			"path", path)
+		logger.Debugw("unlinkat", "path", path)
 		r.recordFileAccess(path, false, false, true)
 	}
 	return nil
@@ -329,7 +323,7 @@ func (r *Result) parseExitSyscall(syscall, args string) error {
 
 // Parse reads an strace and collects the files, sockets and commands that were
 // accessed.
-func Parse(r io.Reader) (*Result, error) {
+func Parse(r io.Reader, logger *zap.SugaredLogger) (*Result, error) {
 	result := &Result{
 		files:            make(map[string]*FileInfo),
 		sockets:          make(map[string]*SocketInfo),
@@ -347,22 +341,18 @@ func Parse(r io.Reader) (*Result, error) {
 
 		match := stracePattern.FindStringSubmatch(line)
 		if match != nil {
-			// Analyze entry events.
 			if match[2] == "E" {
-				err := result.parseEnterSyscall(match[3], match[4])
-				if err != nil {
+				// Analyze entry events.
+				if err := result.parseEnterSyscall(match[3], match[4], logger); err != nil {
 					// Log errors and continue.
 					log.Warn("Failed to parse entry syscall", "error", err)
 				}
 			}
-			// Analyze exit events.
 			if match[2] == "X" {
 				// Analyze exit events.
-				err := result.parseExitSyscall(match[3], match[4])
-				if err != nil {
+				if err := result.parseExitSyscall(match[3], match[4], logger); err != nil {
 					// Log errors and continue.
-					log.Warn("Failed to parse exit syscall",
-						"error", err)
+					log.Warn("Failed to parse exit syscall", "error", err)
 				}
 			}
 		}
diff --git a/internal/worker/rundynamic.go b/internal/worker/rundynamic.go
index b258f473..8cc0336e 100644
--- a/internal/worker/rundynamic.go
+++ b/internal/worker/rundynamic.go
@@ -187,7 +187,7 @@ func RunDynamicAnalysis(pkg *pkgmanager.Pkg, sbOpts []sandbox.Option, analysisCm
 	for _, phase := range analysisrun.DefaultDynamicPhases() {
 		startTime := time.Now()
 		args := dynamicanalysis.MakeAnalysisArgs(pkg, phase)
-		phaseResult, err := dynamicanalysis.Run(sb, analysisCmd, args)
+		phaseResult, err := dynamicanalysis.Run(sb, analysisCmd, args, log.GetDefaultLogger())
 		result.LastRunPhase = phase
 
 		runDuration := time.Since(startTime)


Test patch:
diff --git a/internal/strace/strace_test.go b/internal/strace/strace_test.go
index 6546c3ad..f0b188bb 100644
--- a/internal/strace/strace_test.go
+++ b/internal/strace/strace_test.go
@@ -6,11 +6,15 @@ import (
 	"strings"
 	"testing"
 
+	"go.uber.org/zap"
+
 	"github.com/ossf/package-analysis/internal/log"
 	"github.com/ossf/package-analysis/internal/strace"
 	"github.com/ossf/package-analysis/internal/utils"
 )
 
+var nopLogger = zap.NewNop().Sugar()
+
 func init() {
 	log.Initialize("")
 }
@@ -18,7 +22,7 @@ func init() {
 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)
+	res, err := strace.Parse(r, nopLogger)
 	if err != nil || res == nil {
 		t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}
@@ -37,7 +41,7 @@ func TestParseFileReadThenCreate(t *testing.T) {
 	}
 
 	r := strings.NewReader(input)
-	res, err := strace.Parse(r)
+	res, err := strace.Parse(r, nopLogger)
 	if err != nil || res == nil {
 		t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}
@@ -66,7 +70,7 @@ func TestParseFileWriteMultipleWritesToSameFile(t *testing.T) {
 		WriteInfo: writeInfoWantArray}
 
 	r := strings.NewReader(input)
-	res, err := strace.Parse(r)
+	res, err := strace.Parse(r, nopLogger)
 	if err != nil || res == nil {
 		t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}
@@ -107,7 +111,7 @@ func TestParseFileWritesToDifferentFiles(t *testing.T) {
 	want := []strace.FileInfo{firstFileWant, secondFileWant}
 
 	r := strings.NewReader(input)
-	res, err := strace.Parse(r)
+	res, err := strace.Parse(r, nopLogger)
 	if err != nil || res == nil {
 		t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}
@@ -135,7 +139,7 @@ func TestParseFileWriteWithZeroBytesWritten(t *testing.T) {
 	}
 
 	r := strings.NewReader(input)
-	res, err := strace.Parse(r)
+	res, err := strace.Parse(r, nopLogger)
 	if err != nil || res == nil {
 		t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}
@@ -315,7 +319,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)
+			res, err := strace.Parse(r, nopLogger)
 			if err != nil || res == nil {
 				t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 			}
@@ -332,7 +336,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)
+	res, err := strace.Parse(r, nopLogger)
 	if err != nil || res == nil {
 		t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}
@@ -409,7 +413,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)
+			res, err := strace.Parse(r, nopLogger)
 			if err != nil || res == nil {
 				t.Errorf(`Parse(r) = %v, %v, want _, nil`, res, err)
 			}
@@ -427,7 +431,7 @@ func TestReallyLongLogLine(t *testing.T) {
 	input := fmt.Sprintf(inputTmpl, strings.Repeat(part, 1000))
 
 	r := strings.NewReader(input)
-	res, err := strace.Parse(r)
+	res, err := strace.Parse(r, nopLogger)
 	if err != nil || res == nil {
 		t.Fatalf(`Parse(r) = %v, %v, want _, nil`, res, err)
 	}