pkg/log: adjust fatal errors to the new format

Separate SYZFATAL errors (used by syz-fuzzer) and FATAL errors (used by
syz-ci and syz-manager). For the latter, use the new logging format.

This should facilitate automated error collection.

4 files changed, 35 insertions, 30 deletions

diff --git a/pkg/log/log.go b/pkg/log/log.go
index aee63e6e2..f8a292320 100644
--- a/pkg/log/log.go
+++ b/pkg/log/log.go
@@ -73,22 +73,27 @@ func V(level int) bool {
 }
 
 func Logf(v int, msg string, args ...interface{}) {
-	writeMessage(v, "", msg, args...)
+	writeMessage(v, message("", msg, args...))
 }
 
 func Errorf(msg string, args ...interface{}) {
-	writeMessage(0, "ERROR", msg, args...)
+	writeMessage(0, message("ERROR", msg, args...))
 }
 
 func Fatal(err error) {
-	golog.Fatal("SYZFATAL: ", err)
+	Fatalf("%v", err)
 }
 
 func Fatalf(msg string, args ...interface{}) {
+	golog.Fatalf(message("FATAL", msg, args...))
+}
+
+// SyzFatalf-reported errors are parsed by syzkaller as if they were kernel bugs.
+func SyzFatalf(msg string, args ...interface{}) {
 	golog.Fatalf("SYZFATAL: "+msg, args...)
 }
 
-func writeMessage(v int, severity, msg string, args ...interface{}) {
+func message(severity, msg string, args ...interface{}) string {
 	var sb strings.Builder
 	if severity != "" {
 		fmt.Fprintf(&sb, "[%s] ", severity)
@@ -97,10 +102,10 @@ func writeMessage(v int, severity, msg string, args ...interface{}) {
 		fmt.Fprintf(&sb, "%s: ", instanceName)
 	}
 	fmt.Fprintf(&sb, msg, args...)
-	writeRawMessage(v, sb.String())
+	return sb.String()
 }
 
-func writeRawMessage(v int, msg string) {
+func writeMessage(v int, msg string) {
 	mu.Lock()
 	if cacheEntries != nil && v <= 1 {
 		cacheMem -= len(cacheEntries[cachePos])
diff --git a/syz-fuzzer/fuzzer.go b/syz-fuzzer/fuzzer.go
index 28f35f62c..16304e026 100644
--- a/syz-fuzzer/fuzzer.go
+++ b/syz-fuzzer/fuzzer.go
@@ -163,12 +163,12 @@ func main() {
 
 	target, err := prog.GetTarget(*flagOS, *flagArch)
 	if err != nil {
-		log.Fatalf("%v", err)
+		log.SyzFatalf("%v", err)
 	}
 
 	config, execOpts, err := ipcconfig.Default(target)
 	if err != nil {
-		log.Fatalf("failed to create default ipc config: %v", err)
+		log.SyzFatalf("failed to create default ipc config: %v", err)
 	}
 	if *flagRawCover {
 		execOpts.Flags &^= ipc.FlagDedupCover
@@ -202,7 +202,7 @@ func main() {
 	log.Logf(0, "dialing manager at %v", *flagManager)
 	manager, err := rpctype.NewRPCClient(*flagManager, timeouts.Scale)
 	if err != nil {
-		log.Fatalf("failed to create an RPC client: %v ", err)
+		log.SyzFatalf("failed to create an RPC client: %v ", err)
 	}
 
 	log.Logf(1, "connecting to manager...")
@@ -213,15 +213,15 @@ func main() {
 	}
 	r := &rpctype.ConnectRes{}
 	if err := manager.Call("Manager.Connect", a, r); err != nil {
-		log.Fatalf("failed to call Manager.Connect(): %v ", err)
+		log.SyzFatalf("failed to call Manager.Connect(): %v ", err)
 	}
 	featureFlags, err := csource.ParseFeaturesFlags("none", "none", true)
 	if err != nil {
-		log.Fatal(err)
+		log.SyzFatalf("%v", err)
 	}
 	if r.CoverFilterBitmap != nil {
 		if err := osutil.WriteFile("syz-cover-bitmap", r.CoverFilterBitmap); err != nil {
-			log.Fatalf("failed to write syz-cover-bitmap: %v", err)
+			log.SyzFatalf("failed to write syz-cover-bitmap: %v", err)
 		}
 	}
 	if r.CheckResult == nil {
@@ -239,15 +239,15 @@ func main() {
 		}
 		r.CheckResult.Name = *flagName
 		if err := manager.Call("Manager.Check", r.CheckResult, nil); err != nil {
-			log.Fatalf("Manager.Check call failed: %v", err)
+			log.SyzFatalf("Manager.Check call failed: %v", err)
 		}
 		if r.CheckResult.Error != "" {
-			log.Fatalf("%v", r.CheckResult.Error)
+			log.SyzFatalf("%v", r.CheckResult.Error)
 		}
 	} else {
 		target.UpdateGlobs(r.CheckResult.GlobFiles)
 		if err = host.Setup(target, r.CheckResult.Features, featureFlags, config.Executor); err != nil {
-			log.Fatal(err)
+			log.SyzFatalf("%v", err)
 		}
 	}
 	log.Logf(0, "syscalls: %v", len(r.CheckResult.EnabledCalls[sandbox]))
@@ -304,7 +304,7 @@ func main() {
 	for pid := 0; pid < *flagProcs; pid++ {
 		proc, err := newProc(fuzzer, pid)
 		if err != nil {
-			log.Fatalf("failed to create proc: %v", err)
+			log.SyzFatalf("failed to create proc: %v", err)
 		}
 		fuzzer.procs = append(fuzzer.procs, proc)
 		go proc.loop()
@@ -316,11 +316,11 @@ func main() {
 func collectMachineInfos(target *prog.Target) ([]byte, []host.KernelModule) {
 	machineInfo, err := host.CollectMachineInfo()
 	if err != nil {
-		log.Fatalf("failed to collect machine information: %v", err)
+		log.SyzFatalf("failed to collect machine information: %v", err)
 	}
 	modules, err := host.CollectModulesInfo()
 	if err != nil {
-		log.Fatalf("failed to collect modules info: %v", err)
+		log.SyzFatalf("failed to collect modules info: %v", err)
 	}
 	return machineInfo, modules
 }
@@ -370,7 +370,7 @@ func (fuzzer *Fuzzer) filterDataRaceFrames(frames []string) {
 	timeout := time.Minute * fuzzer.timeouts.Scale
 	output, err := osutil.RunCmd(timeout, "", fuzzer.config.Executor, args...)
 	if err != nil {
-		log.Fatalf("failed to set KCSAN filterlist: %v", err)
+		log.SyzFatalf("failed to set KCSAN filterlist: %v", err)
 	}
 	log.Logf(0, "%s", output)
 }
@@ -423,7 +423,7 @@ func (fuzzer *Fuzzer) poll(needCandidates bool, stats map[string]uint64) bool {
 	}
 	r := &rpctype.PollRes{}
 	if err := fuzzer.manager.Call("Manager.Poll", a, r); err != nil {
-		log.Fatalf("Manager.Poll call failed: %v", err)
+		log.SyzFatalf("Manager.Poll call failed: %v", err)
 	}
 	maxSignal := r.MaxSignal.Deserialize()
 	log.Logf(1, "poll: candidates=%v inputs=%v signal=%v",
@@ -447,7 +447,7 @@ func (fuzzer *Fuzzer) sendInputToManager(inp rpctype.Input) {
 		Input: inp,
 	}
 	if err := fuzzer.manager.Call("Manager.NewInput", a, nil); err != nil {
-		log.Fatalf("Manager.NewInput call failed: %v", err)
+		log.SyzFatalf("Manager.NewInput call failed: %v", err)
 	}
 }
 
@@ -482,7 +482,7 @@ func (fuzzer *Fuzzer) addCandidateInput(candidate rpctype.Candidate) {
 func (fuzzer *Fuzzer) deserializeInput(inp []byte) *prog.Prog {
 	p, err := fuzzer.target.Deserialize(inp, prog.NonStrict)
 	if err != nil {
-		log.Fatalf("failed to deserialize prog: %v\n%s", err, inp)
+		log.SyzFatalf("failed to deserialize prog: %v\n%s", err, inp)
 	}
 	// We build choice table only after we received the initial corpus,
 	// so we don't check the initial corpus here, we check it later in BuildChoiceTable.
@@ -626,7 +626,7 @@ func parseOutputType(str string) OutputType {
 	case "file":
 		return OutputFile
 	default:
-		log.Fatalf("-output flag must be one of none/stdout/dmesg/file")
+		log.SyzFatalf("-output flag must be one of none/stdout/dmesg/file")
 		return OutputNone
 	}
 }
diff --git a/syz-fuzzer/proc.go b/syz-fuzzer/proc.go
index 00d8cec1e..2ca72107a 100644
--- a/syz-fuzzer/proc.go
+++ b/syz-fuzzer/proc.go
@@ -77,7 +77,7 @@ func (proc *Proc) loop() {
 			case *WorkSmash:
 				proc.smashInput(item)
 			default:
-				log.Fatalf("unknown work type: %#v", item)
+				log.SyzFatalf("unknown work type: %#v", item)
 			}
 			continue
 		}
@@ -335,7 +335,7 @@ func (proc *Proc) executeRaw(opts *ipc.ExecOpts, p *prog.Prog, stat Stat) *ipc.P
 				return nil
 			}
 			if try > 10 {
-				log.Fatalf("executor %v failed %v times: %v", proc.pid, try, err)
+				log.SyzFatalf("executor %v failed %v times: %v", proc.pid, try, err)
 			}
 			log.Logf(4, "fuzzer detected executor failure='%v', retrying #%d", err, try+1)
 			debug.FreeOSMemory()
@@ -380,6 +380,6 @@ func (proc *Proc) logProgram(opts *ipc.ExecOpts, p *prog.Prog) {
 			f.Close()
 		}
 	default:
-		log.Fatalf("unknown output type: %v", proc.fuzzer.outputType)
+		log.SyzFatalf("unknown output type: %v", proc.fuzzer.outputType)
 	}
 }
diff --git a/syz-fuzzer/testing.go b/syz-fuzzer/testing.go
index 5474d540c..49f2d1ce6 100644
--- a/syz-fuzzer/testing.go
+++ b/syz-fuzzer/testing.go
@@ -35,11 +35,11 @@ func testImage(hostAddr string, args *checkArgs) {
 	log.Logf(0, "connecting to host at %v", hostAddr)
 	conn, err := rpctype.Dial(hostAddr, args.ipcConfig.Timeouts.Scale)
 	if err != nil {
-		log.Fatalf("BUG: failed to connect to host: %v", err)
+		log.SyzFatalf("BUG: failed to connect to host: %v", err)
 	}
 	conn.Close()
 	if _, err := checkMachine(args); err != nil {
-		log.Fatalf("BUG: %v", err)
+		log.SyzFatalf("BUG: %v", err)
 	}
 }
 
@@ -48,7 +48,7 @@ func runTest(target *prog.Target, manager *rpctype.RPCClient, name, executor str
 	for {
 		req := new(rpctype.RunTestPollRes)
 		if err := manager.Call("Manager.Poll", pollReq, req); err != nil {
-			log.Fatalf("Manager.Poll call failed: %v", err)
+			log.SyzFatalf("Manager.Poll call failed: %v", err)
 		}
 		if len(req.Bin) == 0 && len(req.Prog) == 0 {
 			return
@@ -67,7 +67,7 @@ func runTest(target *prog.Target, manager *rpctype.RPCClient, name, executor str
 			reply.Error = test.Err.Error()
 		}
 		if err := manager.Call("Manager.Done", reply, nil); err != nil {
-			log.Fatalf("Manager.Done call failed: %v", err)
+			log.SyzFatalf("Manager.Done call failed: %v", err)
 		}
 	}
 }