log: add package

Log is a simple wrapper around std log package.
It is meant to solve 2 main problems:
1. Logging from non-main packages (mainly, vm/* packages).
   Currently they can either always log or not log at all.
   But they can't respect program verbosity setting.
   Log package allows all packages to use the same verbosity setting.
2. Exposing recent logs in html UI.
   Namely we want to tee logs to console and html UI.

3 files changed, 51 insertions, 55 deletions

diff --git a/tools/syz-execprog/execprog.go b/tools/syz-execprog/execprog.go
index d331c4e5d..48a686e7f 100644
--- a/tools/syz-execprog/execprog.go
+++ b/tools/syz-execprog/execprog.go
@@ -11,7 +11,6 @@ import (
 	"flag"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"os"
 	"os/signal"
 	"sync"
@@ -21,6 +20,7 @@ import (
 
 	"github.com/google/syzkaller/cover"
 	"github.com/google/syzkaller/ipc"
+	. "github.com/google/syzkaller/log"
 	"github.com/google/syzkaller/prog"
 )
 
@@ -44,21 +44,21 @@ func main() {
 	for _, fn := range flag.Args() {
 		data, err := ioutil.ReadFile(fn)
 		if err != nil {
-			log.Fatalf("failed to read log file: %v", err)
+			Fatalf("failed to read log file: %v", err)
 		}
 		entries := prog.ParseLog(data)
 		for _, ent := range entries {
 			progs = append(progs, ent.P)
 		}
 	}
-	log.Printf("parsed %v programs", len(progs))
+	Logf(0, "parsed %v programs", len(progs))
 	if len(progs) == 0 {
 		return
 	}
 
 	flags, timeout, err := ipc.DefaultFlags()
 	if err != nil {
-		log.Fatalf("%v", err)
+		Fatalf("%v", err)
 	}
 	if *flagCoverFile != "" {
 		flags |= ipc.FlagCover
@@ -78,7 +78,7 @@ func main() {
 			defer wg.Done()
 			env, err := ipc.MakeEnv(*flagExecutor, timeout, flags)
 			if err != nil {
-				log.Fatalf("failed to create ipc env: %v", err)
+				Fatalf("failed to create ipc env: %v", err)
 			}
 			defer env.Close()
 			for {
@@ -91,7 +91,7 @@ func main() {
 					idx := pos
 					pos++
 					if idx%len(progs) == 0 && time.Since(lastPrint) > 5*time.Second {
-						log.Printf("executed programs: %v", idx)
+						Logf(0, "executed programs: %v", idx)
 						lastPrint = time.Now()
 					}
 					posMu.Unlock()
@@ -103,7 +103,7 @@ func main() {
 					case "stdout":
 						data := p.Serialize()
 						logMu.Lock()
-						log.Printf("executing program %v:\n%s", pid, data)
+						Logf(0, "executing program %v:\n%s", pid, data)
 						logMu.Unlock()
 					}
 					output, cov, _, failed, hanged, err := env.Exec(p)
@@ -132,7 +132,7 @@ func main() {
 							}
 							err := ioutil.WriteFile(fmt.Sprintf("%v.%v", *flagCoverFile, i), buf.Bytes(), 0660)
 							if err != nil {
-								log.Fatalf("failed to write coverage file: %v", err)
+								Fatalf("failed to write coverage file: %v", err)
 							}
 						}
 					}
@@ -148,10 +148,10 @@ func main() {
 		c := make(chan os.Signal, 2)
 		signal.Notify(c, syscall.SIGINT)
 		<-c
-		log.Printf("shutting down...")
+		Logf(0, "shutting down...")
 		atomic.StoreUint32(&shutdown, 1)
 		<-c
-		log.Fatalf("terminating")
+		Fatalf("terminating")
 	}()
 
 	wg.Wait()
diff --git a/tools/syz-repro/repro.go b/tools/syz-repro/repro.go
index de685acce..27e6c1cd9 100644
--- a/tools/syz-repro/repro.go
+++ b/tools/syz-repro/repro.go
@@ -7,7 +7,6 @@ import (
 	"flag"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"os"
 	"os/signal"
 	"path/filepath"
@@ -18,6 +17,7 @@ import (
 	"github.com/google/syzkaller/config"
 	"github.com/google/syzkaller/csource"
 	"github.com/google/syzkaller/fileutil"
+	. "github.com/google/syzkaller/log"
 	"github.com/google/syzkaller/prog"
 	"github.com/google/syzkaller/report"
 	"github.com/google/syzkaller/vm"
@@ -47,24 +47,24 @@ func main() {
 	flag.Parse()
 	cfg, _, _, err := config.Parse(*flagConfig)
 	if err != nil {
-		log.Fatalf("%v", err)
+		Fatalf("%v", err)
 	}
 	if *flagCount > 0 {
 		cfg.Count = *flagCount
 	}
 	if _, err := os.Stat(filepath.Join(cfg.Syzkaller, "bin/syz-execprog")); err != nil {
-		log.Fatalf("bin/syz-execprog is missing (run 'make execprog')")
+		Fatalf("bin/syz-execprog is missing (run 'make execprog')")
 	}
 
 	if len(flag.Args()) != 1 {
-		log.Fatalf("usage: syz-repro -config=config.file execution.log")
+		Fatalf("usage: syz-repro -config=config.file execution.log")
 	}
 	data, err := ioutil.ReadFile(flag.Args()[0])
 	if err != nil {
-		log.Fatalf("failed to open log file: %v", err)
+		Fatalf("failed to open log file: %v", err)
 	}
 	entries := prog.ParseLog(data)
-	log.Printf("parsed %v programs", len(entries))
+	Logf(0, "parsed %v programs", len(entries))
 
 	crashDesc, _, crashStart, _ := report.Parse(data)
 	if crashDesc == "" {
@@ -79,19 +79,19 @@ func main() {
 			for index := range bootRequests {
 				vmCfg, err := config.CreateVMConfig(cfg, index)
 				if err != nil {
-					log.Fatalf("failed to create VM config: %v", err)
+					Fatalf("failed to create VM config: %v", err)
 				}
 				inst, err := vm.Create(cfg.Type, vmCfg)
 				if err != nil {
-					log.Fatalf("failed to create VM: %v", err)
+					Fatalf("failed to create VM: %v", err)
 				}
 				execprogBin, err := inst.Copy(filepath.Join(cfg.Syzkaller, "bin/syz-execprog"))
 				if err != nil {
-					log.Fatalf("failed to copy to VM: %v", err)
+					Fatalf("failed to copy to VM: %v", err)
 				}
 				executorBin, err := inst.Copy(filepath.Join(cfg.Syzkaller, "bin/syz-executor"))
 				if err != nil {
-					log.Fatalf("failed to copy to VM: %v", err)
+					Fatalf("failed to copy to VM: %v", err)
 				}
 				instances <- VM{inst, index, execprogBin, executorBin}
 			}
@@ -103,9 +103,9 @@ func main() {
 		signal.Notify(c, syscall.SIGINT)
 		<-c
 		close(shutdown)
-		log.Printf("shutting down...")
+		Logf(-1, "shutting down...")
 		<-c
-		log.Fatalf("terminating")
+		Fatalf("terminating")
 	}()
 
 	repro(cfg, entries, crashStart)
@@ -146,9 +146,9 @@ func repro(cfg *config.Config, entries []*prog.LogEntry, crashStart int) {
 		suspected = append(suspected, entries[indices[i]])
 	}
 	// Execute the suspected programs.
-	log.Printf("the suspected programs are:")
+	Logf(0, "the suspected programs are:")
 	for _, ent := range suspected {
-		log.Printf("on proc %v:\n%s\n", ent.Proc, ent.P.Serialize())
+		Logf(0, "on proc %v:\n%s\n", ent.Proc, ent.P.Serialize())
 	}
 	var p *prog.Prog
 	multiplier := 1
@@ -161,10 +161,10 @@ func repro(cfg *config.Config, entries []*prog.LogEntry, crashStart int) {
 		}
 	}
 	if p == nil {
-		log.Printf("no program crashed")
+		Logf(0, "no program crashed")
 		return
 	}
-	log.Printf("minimizing program")
+	Logf(0, "minimizing program")
 
 	p, _ = prog.Minimize(p, -1, func(p1 *prog.Prog, callIndex int) bool {
 		return testProg(cfg, p1, multiplier, true, true)
@@ -183,14 +183,14 @@ func repro(cfg *config.Config, entries []*prog.LogEntry, crashStart int) {
 
 	src := csource.Write(p, opts)
 	src, _ = csource.Format(src)
-	log.Printf("C source:\n%s\n", src)
+	Logf(0, "C source:\n%s\n", src)
 	srcf, err := fileutil.WriteTempFile(src)
 	if err != nil {
-		log.Fatalf("%v", err)
+		Fatalf("%v", err)
 	}
 	bin, err := csource.Build(srcf)
 	if err != nil {
-		log.Fatalf("%v", err)
+		Fatalf("%v", err)
 	}
 	defer os.Remove(bin)
 	testBin(cfg, bin)
@@ -208,7 +208,7 @@ func returnInstance(inst VM, res bool) {
 }
 
 func testProg(cfg *config.Config, p *prog.Prog, multiplier int, threaded, collide bool) (res bool) {
-	log.Printf("booting VM")
+	Logf(0, "booting VM")
 	var inst VM
 	select {
 	case inst = <-instances:
@@ -222,12 +222,12 @@ func testProg(cfg *config.Config, p *prog.Prog, multiplier int, threaded, collid
 	pstr := p.Serialize()
 	progFile, err := fileutil.WriteTempFile(pstr)
 	if err != nil {
-		log.Fatalf("%v", err)
+		Fatalf("%v", err)
 	}
 	defer os.Remove(progFile)
 	bin, err := inst.Copy(progFile)
 	if err != nil {
-		log.Fatalf("failed to copy to VM: %v", err)
+		Fatalf("failed to copy to VM: %v", err)
 	}
 
 	repeat := 100
@@ -241,13 +241,13 @@ func testProg(cfg *config.Config, p *prog.Prog, multiplier int, threaded, collid
 	timeout := time.Duration(timeoutSec) * time.Second
 	command := fmt.Sprintf("%v -executor %v -cover=0 -procs=%v -repeat=%v -sandbox %v -threaded=%v -collide=%v %v",
 		inst.execprogBin, inst.executorBin, cfg.Procs, repeat, cfg.Sandbox, threaded, collide, bin)
-	log.Printf("testing program (threaded=%v, collide=%v, repeat=%v, timeout=%v):\n%s\n",
+	Logf(0, "testing program (threaded=%v, collide=%v, repeat=%v, timeout=%v):\n%s\n",
 		threaded, collide, repeat, timeout, pstr)
 	return testImpl(inst, command, timeout)
 }
 
 func testBin(cfg *config.Config, bin string) (res bool) {
-	log.Printf("booting VM")
+	Logf(0, "booting VM")
 	var inst VM
 	select {
 	case inst = <-instances:
@@ -260,23 +260,23 @@ func testBin(cfg *config.Config, bin string) (res bool) {
 
 	bin, err := inst.Copy(bin)
 	if err != nil {
-		log.Fatalf("failed to copy to VM: %v", err)
+		Fatalf("failed to copy to VM: %v", err)
 	}
-	log.Printf("testing compiled C program")
+	Logf(0, "testing compiled C program")
 	return testImpl(inst, bin, 10*time.Second)
 }
 
 func testImpl(inst vm.Instance, command string, timeout time.Duration) (res bool) {
 	outc, errc, err := inst.Run(timeout, command)
 	if err != nil {
-		log.Fatalf("failed to run command in VM: %v", err)
+		Fatalf("failed to run command in VM: %v", err)
 	}
 	desc, text, output, crashed, timedout := vm.MonitorExecution(outc, errc, false, false)
 	_, _ = text, output
 	if crashed || timedout {
-		log.Printf("program crashed with: %v", desc)
+		Logf(0, "program crashed with: %v", desc)
 		return true
 	}
-	log.Printf("program did not crash")
+	Logf(0, "program did not crash")
 	return false
 }
diff --git a/tools/syz-stress/stress.go b/tools/syz-stress/stress.go
index 0507f0f5c..12665f66f 100644
--- a/tools/syz-stress/stress.go
+++ b/tools/syz-stress/stress.go
@@ -8,7 +8,6 @@ import (
 	"flag"
 	"fmt"
 	"io/ioutil"
-	"log"
 	"math/rand"
 	"os"
 	"regexp"
@@ -19,6 +18,7 @@ import (
 
 	"github.com/google/syzkaller/host"
 	"github.com/google/syzkaller/ipc"
+	. "github.com/google/syzkaller/log"
 	"github.com/google/syzkaller/prog"
 	"github.com/google/syzkaller/sys"
 )
@@ -41,7 +41,7 @@ const programLength = 30
 func main() {
 	flag.Parse()
 	corpus := readCorpus()
-	log.Printf("parsed %v programs", len(corpus))
+	Logf(0, "parsed %v programs", len(corpus))
 
 	calls := buildCallList()
 	prios := prog.CalculatePriorities(corpus)
@@ -49,7 +49,7 @@ func main() {
 
 	flags, timeout, err := ipc.DefaultFlags()
 	if err != nil {
-		failf("%v", err)
+		Fatalf("%v", err)
 	}
 	gate = ipc.NewGate(2**flagProcs, nil)
 	for pid := 0; pid < *flagProcs; pid++ {
@@ -57,7 +57,7 @@ func main() {
 		go func() {
 			env, err := ipc.MakeEnv(*flagExecutor, timeout, flags)
 			if err != nil {
-				failf("failed to create execution environment: %v", err)
+				Fatalf("failed to create execution environment: %v", err)
 			}
 			rs := rand.NewSource(time.Now().UnixNano() + int64(pid)*1e12)
 			rnd := rand.New(rs)
@@ -79,7 +79,7 @@ func main() {
 		}()
 	}
 	for range time.NewTicker(5 * time.Second).C {
-		log.Printf("executed %v programs", atomic.LoadUint64(&statExec))
+		Logf(0, "executed %v programs", atomic.LoadUint64(&statExec))
 	}
 }
 
@@ -117,21 +117,21 @@ func readCorpus() []*prog.Prog {
 	}
 	zipr, err := zip.OpenReader(*flagCorpus)
 	if err != nil {
-		failf("failed to open bin file: %v", err)
+		Fatalf("failed to open bin file: %v", err)
 	}
 	var progs []*prog.Prog
 	for _, zipf := range zipr.File {
 		r, err := zipf.Open()
 		if err != nil {
-			failf("failed to uzip file from input archive: %v", err)
+			Fatalf("failed to uzip file from input archive: %v", err)
 		}
 		data, err := ioutil.ReadAll(r)
 		if err != nil {
-			failf("failed to read corpus file: %v", err)
+			Fatalf("failed to read corpus file: %v", err)
 		}
 		p, err := prog.Deserialize(data)
 		if err != nil {
-			failf("failed to deserialize corpus program: %v", err)
+			Fatalf("failed to deserialize corpus program: %v", err)
 		}
 		progs = append(progs, p)
 		r.Close()
@@ -143,7 +143,7 @@ func readCorpus() []*prog.Prog {
 func buildCallList() map[*sys.Call]bool {
 	calls, err := host.DetectSupportedSyscalls()
 	if err != nil {
-		log.Printf("failed to detect host supported syscalls: %v", err)
+		Logf(0, "failed to detect host supported syscalls: %v", err)
 		calls = make(map[*sys.Call]bool)
 		for _, c := range sys.Calls {
 			calls[c] = true
@@ -151,19 +151,15 @@ func buildCallList() map[*sys.Call]bool {
 	}
 	for _, c := range sys.Calls {
 		if !calls[c] {
-			log.Printf("disabling unsupported syscall: %v", c.Name)
+			Logf(0, "disabling unsupported syscall: %v", c.Name)
 		}
 	}
 	trans := sys.TransitivelyEnabledCalls(calls)
 	for c := range calls {
 		if !trans[c] {
-			log.Printf("disabling transitively unsupported syscall: %v", c.Name)
+			Logf(0, "disabling transitively unsupported syscall: %v", c.Name)
 			delete(calls, c)
 		}
 	}
 	return calls
 }
-
-func failf(msg string, args ...interface{}) {
-	log.Fatalf(msg, args...)
-}