diff --git a/log/log.go b/log/log.go new file mode 100644 index 00000000..752b72bd --- /dev/null +++ b/log/log.go @@ -0,0 +1,99 @@ +// Copyright 2016 syzkaller project authors. All rights reserved. +// Use of this source code is governed by Apache 2 LICENSE that can be found in the LICENSE file. + +// log package provides functionality similar to standard log package with some extensions: +// - verbosity levels +// - global verbosity setting that can be used by multiple packages +// - ability to disable all output +// - ability to cache recent output in memory +package log + +import ( + "bytes" + "flag" + "fmt" + golog "log" + "sync" +) + +var ( + flagV = flag.Int("v", 0, "verbosity") + mu sync.Mutex + disabled bool + cacheMem int + cacheMaxMem int + cachePos int + cacheEntries []string +) + +// EnableCaching enables in memory caching of log output. +// Caches up to maxLines, but no more than maxMem bytes. +// Cached output can later be queried with CachedOutput. +func EnableLogCaching(maxLines, maxMem int) { + mu.Lock() + defer mu.Unlock() + if cacheEntries != nil { + Fatalf("log caching is already enabled") + } + if maxLines < 1 || maxMem < 1 { + panic("invalid maxLines/maxMem") + } + cacheMaxMem = maxMem + cacheEntries = make([]string, maxLines) +} + +// Retrieves cached log output. +func CachedLogOutput() string { + mu.Lock() + defer mu.Unlock() + buf := new(bytes.Buffer) + for i := range cacheEntries { + pos := (cachePos + i) % len(cacheEntries) + if cacheEntries[pos] == "" { + continue + } + buf.WriteString(cacheEntries[pos]) + buf.Write([]byte{'\n'}) + } + return buf.String() +} + +func DisableLog() { + mu.Lock() + defer mu.Unlock() + disabled = true +} + +func Logf(v int, msg string, args ...interface{}) { + mu.Lock() + doLog := v <= *flagV && (v < 0 || !disabled) + if cacheEntries != nil { + cacheMem -= len(cacheEntries[cachePos]) + if cacheMem < 0 { + panic("log cache size underflow") + } + cacheEntries[cachePos] = fmt.Sprintf(msg, args...) + cacheMem += len(cacheEntries[cachePos]) + cachePos++ + if cachePos == len(cacheEntries) { + cachePos = 0 + } + for i := 0; i < len(cacheEntries)-1 && cacheMem > cacheMaxMem; i++ { + pos := (cachePos + i) % len(cacheEntries) + cacheMem -= len(cacheEntries[pos]) + cacheEntries[pos] = "" + } + if cacheMem < 0 { + panic("log cache size underflow") + } + } + mu.Unlock() + + if doLog { + golog.Printf(msg, args...) + } +} + +func Fatalf(msg string, args ...interface{}) { + golog.Fatalf(msg, args...) +} diff --git a/log/log_test.go b/log/log_test.go new file mode 100644 index 00000000..e21a8a78 --- /dev/null +++ b/log/log_test.go @@ -0,0 +1,31 @@ +// Copyright 2016 syzkaller project authors. All rights reserved. +// Use of this source code is governed by Apache 2 LICENSE that can be found in the LICENSE file. + +package log + +import ( + "testing" +) + +func TestCaching(t *testing.T) { + tests := []struct{ str, want string }{ + {"", ""}, + {"a", "a\n"}, + {"bb", "a\nbb\n"}, + {"ccc", "a\nbb\nccc\n"}, + {"dddd", "a\nbb\nccc\ndddd\n"}, + {"eeeee", "bb\nccc\ndddd\neeeee\n"}, + {"ffffff", "ccc\ndddd\neeeee\nffffff\n"}, + {"ggggggg", "eeeee\nffffff\nggggggg\n"}, + {"hhhhhhhh", "ggggggg\nhhhhhhhh\n"}, + {"jjjjjjjjjjjjjjjjjjjjjjjjj", "jjjjjjjjjjjjjjjjjjjjjjjjj\n"}, + } + EnableLogCaching(4, 20) + for _, test := range tests { + Logf(1000, test.str) + out := CachedLogOutput() + if out != test.want { + t.Fatalf("wrote: %v\nwant: %v\ngot: %v", test.str, test.want, out) + } + } +} diff --git a/syz-fuzzer/fuzzer.go b/syz-fuzzer/fuzzer.go index f1dcb75e..de753c8b 100644 --- a/syz-fuzzer/fuzzer.go +++ b/syz-fuzzer/fuzzer.go @@ -12,7 +12,6 @@ import ( "crypto/sha1" "flag" "fmt" - "log" "math/rand" "net/rpc" "net/rpc/jsonrpc" @@ -28,6 +27,7 @@ import ( "github.com/google/syzkaller/cover" "github.com/google/syzkaller/host" "github.com/google/syzkaller/ipc" + . "github.com/google/syzkaller/log" "github.com/google/syzkaller/prog" . "github.com/google/syzkaller/rpctype" "github.com/google/syzkaller/sys" @@ -39,7 +39,6 @@ var ( flagManager = flag.String("manager", "", "manager rpc address") flagProcs = flag.Int("procs", 1, "number of parallel test processes") flagLeak = flag.Bool("leak", false, "detect memory leaks") - flagV = flag.Int("v", 0, "verbosity") flagOutput = flag.String("output", "stdout", "write programs to none/stdout/dmesg/file") ) @@ -97,13 +96,13 @@ func main() { fmt.Fprintf(os.Stderr, "-output flag must be one of none/stdout/dmesg/file\n") os.Exit(1) } - logf(0, "fuzzer started, log level %v", *flagV) + Logf(0, "fuzzer started") corpusCover = make([]cover.Cover, sys.CallCount) maxCover = make([]cover.Cover, sys.CallCount) corpusHashes = make(map[Sig]struct{}) - logf(0, "dialing manager at %v", *flagManager) + Logf(0, "dialing manager at %v", *flagManager) conn, err := jsonrpc.Dial("tcp", *flagManager) if err != nil { panic(err) @@ -127,7 +126,7 @@ func main() { if !noCover { fd, err := syscall.Open("/sys/kernel/debug/kcov", syscall.O_RDWR, 0) if err != nil { - log.Fatalf("BUG: /sys/kernel/debug/kcov is missing (%v). Enable CONFIG_KCOV and mount debugfs.", err) + Fatalf("BUG: /sys/kernel/debug/kcov is missing (%v). Enable CONFIG_KCOV and mount debugfs.", err) } syscall.Close(fd) } @@ -173,7 +172,7 @@ func main() { default: } } - logf(1, "triaging : %s", inp.p) + Logf(1, "triaging : %s", inp.p) triageInput(pid, env, inp) continue } else if len(candidates) != 0 { @@ -194,17 +193,17 @@ func main() { if len(corpus) == 0 || i%10 == 0 { corpusMu.RUnlock() p := prog.Generate(rnd, programLength, ct) - logf(1, "#%v: generated: %s", i, p) + Logf(1, "#%v: generated: %s", i, p) execute(pid, env, p, &statExecGen) p.Mutate(rnd, programLength, ct) - logf(1, "#%v: mutated: %s", i, p) + Logf(1, "#%v: mutated: %s", i, p) execute(pid, env, p, &statExecFuzz) } else { p0 := corpus[rnd.Intn(len(corpus))] corpusMu.RUnlock() p := p0.Clone() p.Mutate(rs, programLength, ct) - logf(1, "#%v: mutated: %s <- %s", i, p, p0) + Logf(1, "#%v: mutated: %s <- %s", i, p, p0) execute(pid, env, p, &statExecFuzz) } } @@ -223,7 +222,7 @@ func main() { } if *flagOutput != "stdout" && time.Since(lastPrint) > 10*time.Second { // Keep-alive for manager. - logf(0, "alive") + Logf(0, "alive") lastPrint = time.Now() } if poll || time.Since(lastPoll) > 10*time.Second { @@ -302,11 +301,11 @@ func buildCallList(enabledCalls string) map[*sys.Call]bool { } if supp, err := host.DetectSupportedSyscalls(); err != nil { - logf(0, "failed to detect host supported syscalls: %v", err) + Logf(0, "failed to detect host supported syscalls: %v", err) } else { for c := range calls { if !supp[c] { - logf(1, "disabling unsupported syscall: %v", c.Name) + Logf(1, "disabling unsupported syscall: %v", c.Name) delete(calls, c) } } @@ -315,7 +314,7 @@ func buildCallList(enabledCalls string) map[*sys.Call]bool { trans := sys.TransitivelyEnabledCalls(calls) for c := range calls { if !trans[c] { - logf(1, "disabling transitively unsupported syscall: %v", c.Name) + Logf(1, "disabling transitively unsupported syscall: %v", c.Name) delete(calls, c) } } @@ -418,7 +417,7 @@ func triageInput(pid int, env *ipc.Env, inp Input) { atomic.AddUint64(&statNewInput, 1) data := inp.p.Serialize() - logf(2, "added new input for %v to corpus:\n%s", call.CallName, data) + Logf(2, "added new input for %v to corpus:\n%s", call.CallName, data) a := &NewInputArgs{*flagName, RpcInput{call.CallName, data, inp.call, []uint32(inp.cover)}} if err := manager.Call("Manager.NewInput", a, nil); err != nil { panic(err) @@ -485,7 +484,7 @@ func execute1(pid int, env *ipc.Env, p *prog.Prog, stat *uint64) []cover.Cover { 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() case "dmesg": fd, err := syscall.Open("/dev/kmsg", syscall.O_WRONLY, 0) @@ -510,7 +509,7 @@ retry: _ = errnos if failed { // BUG in output should be recognized by manager. - logf(0, "BUG: executor-detected bug:\n%s", output) + Logf(0, "BUG: executor-detected bug:\n%s", output) // Don't return any cover so that the input is not added to corpus. return make([]cover.Cover, len(p.Calls)) } @@ -519,12 +518,12 @@ retry: panic(err) } try++ - logf(4, "fuzzer detected executor failure='%v', retrying #%d\n", err, (try + 1)) + Logf(4, "fuzzer detected executor failure='%v', retrying #%d\n", err, (try + 1)) debug.FreeOSMemory() time.Sleep(time.Second) goto retry } - logf(2, "result failed=%v hanged=%v:\n%v\n", failed, hanged, string(output)) + Logf(2, "result failed=%v hanged=%v:\n%v\n", failed, hanged, string(output)) cov := make([]cover.Cover, len(p.Calls)) for i, c := range rawCover { cov[i] = cover.Cover(c) @@ -532,17 +531,11 @@ retry: return cov } -func logf(v int, msg string, args ...interface{}) { - if *flagV >= v { - log.Printf(msg, args...) - } -} - func kmemleakInit() { fd, err := syscall.Open("/sys/kernel/debug/kmemleak", syscall.O_RDWR, 0) if err != nil { if *flagLeak { - log.Fatalf("BUG: /sys/kernel/debug/kmemleak is missing (%v). Enable CONFIG_KMEMLEAK and mount debugfs.", err) + Fatalf("BUG: /sys/kernel/debug/kmemleak is missing (%v). Enable CONFIG_KMEMLEAK and mount debugfs.", err) } else { return } @@ -602,7 +595,7 @@ func kmemleakScan(report bool) { } if n != 0 { // BUG in output should be recognized by manager. - logf(0, "BUG: memory leak:\n%s\n", kmemleakBuf[:n]) + Logf(0, "BUG: memory leak:\n%s\n", kmemleakBuf[:n]) } } } diff --git a/syz-gce/syz-gce.go b/syz-gce/syz-gce.go index d4487752..b5c4ac24 100644 --- a/syz-gce/syz-gce.go +++ b/syz-gce/syz-gce.go @@ -11,7 +11,6 @@ import ( "fmt" "io" "io/ioutil" - "log" "os" "os/exec" "path/filepath" @@ -21,6 +20,7 @@ import ( "cloud.google.com/go/storage" "github.com/google/syzkaller/config" "github.com/google/syzkaller/gce" + . "github.com/google/syzkaller/log" "golang.org/x/net/context" ) @@ -51,81 +51,81 @@ func main() { gopath, err := filepath.Abs("gopath") if err != nil { - fatalf("failed to get absolute path: %v", err) + Fatalf("failed to get absolute path: %v", err) } os.Setenv("GOPATH", gopath) ctx = context.Background() storageClient, err = storage.NewClient(ctx) if err != nil { - fatalf("failed to create cloud storage client: %v", err) + Fatalf("failed to create cloud storage client: %v", err) } GCE, err = gce.NewContext() if err != nil { - log.Fatalf("failed to init gce: %v", err) + Fatalf("failed to init gce: %v", err) } - log.Printf("gce initialized: running on %v, internal IP, %v project %v, zone %v", GCE.Instance, GCE.InternalIP, GCE.ProjectID, GCE.ZoneID) + Logf(0, "gce initialized: running on %v, internal IP, %v project %v, zone %v", GCE.Instance, GCE.InternalIP, GCE.ProjectID, GCE.ZoneID) - log.Printf("downloading image archive...") + Logf(0, "downloading image archive...") archive, updated, err := openFile(cfg.Image_Archive) if err != nil { - fatalf("%v", err) + Fatalf("%v", err) } _ = updated if err := os.RemoveAll("image"); err != nil { - fatalf("failed to remove image dir: %v", err) + Fatalf("failed to remove image dir: %v", err) } if err := downloadAndExtract(archive, "image"); err != nil { - fatalf("failed to download and extract %v: %v", cfg.Image_Archive, err) + Fatalf("failed to download and extract %v: %v", cfg.Image_Archive, err) } - log.Printf("uploading image...") + Logf(0, "uploading image...") if err := uploadFile("image/disk.tar.gz", cfg.Image_Path); err != nil { - fatalf("failed to upload image: %v", err) + Fatalf("failed to upload image: %v", err) } - log.Printf("creating gce image...") + Logf(0, "creating gce image...") if err := GCE.DeleteImage(cfg.Image_Name); err != nil { - fatalf("failed to delete GCE image: %v", err) + Fatalf("failed to delete GCE image: %v", err) } if err := GCE.CreateImage(cfg.Image_Name, cfg.Image_Path); err != nil { - fatalf("failed to create GCE image: %v", err) + Fatalf("failed to create GCE image: %v", err) } - log.Printf("building syzkaller...") + Logf(0, "building syzkaller...") syzBin, err := updateSyzkallerBuild() if err != nil { - fatalf("failed to update/build syzkaller: %v", err) + Fatalf("failed to update/build syzkaller: %v", err) } _ = syzBin - log.Printf("starting syzkaller...") + Logf(0, "starting syzkaller...") if err := writeManagerConfig("manager.cfg"); err != nil { - fatalf("failed to write manager config: %v", err) + Fatalf("failed to write manager config: %v", err) } manager := exec.Command("gopath/src/github.com/google/syzkaller/bin/syz-manager", "-config=manager.cfg") manager.Stdout = os.Stdout manager.Stderr = os.Stderr if err := manager.Start(); err != nil { - fatalf("failed to start syz-manager: %v", err) + Fatalf("failed to start syz-manager: %v", err) } err = manager.Wait() - fatalf("syz-manager exited with: %v", err) + Fatalf("syz-manager exited with: %v", err) } func readConfig(filename string) *Config { if filename == "" { - fatalf("supply config in -config flag") + Fatalf("supply config in -config flag") } data, err := ioutil.ReadFile(filename) if err != nil { - fatalf("failed to read config file: %v", err) + Fatalf("failed to read config file: %v", err) } cfg := new(Config) if err := json.Unmarshal(data, cfg); err != nil { - fatalf("failed to parse config file: %v", err) + Fatalf("failed to parse config file: %v", err) } return cfg } @@ -196,7 +196,7 @@ func downloadAndExtract(f *storage.ObjectHandle, dir string) error { if err != nil { return err } - log.Printf("extracting file: %v (%v bytes)", hdr.Name, hdr.Size) + Logf(0, "extracting file: %v (%v bytes)", hdr.Name, hdr.Size) if len(hdr.Name) == 0 || hdr.Name[len(hdr.Name)-1] == '/' { continue } @@ -247,7 +247,3 @@ func updateSyzkallerBuild() (string, error) { } return "gopath/src/github.com/google/syzkaller/bin", nil } - -func fatalf(msg string, args ...interface{}) { - log.Fatalf(msg, args...) -} diff --git a/syz-manager/cover.go b/syz-manager/cover.go index 4e10c687..3fe7a799 100644 --- a/syz-manager/cover.go +++ b/syz-manager/cover.go @@ -16,6 +16,7 @@ import ( "strings" "github.com/google/syzkaller/cover" + . "github.com/google/syzkaller/log" "github.com/google/syzkaller/symbolizer" ) @@ -61,7 +62,7 @@ func initAllCover(vmlinux string) { sort.Sort(uint64Array(pcs)) allCoverPCs = pcs } else { - logf(0, "failed to run objdump on %v: %v", vmlinux, err) + Logf(0, "failed to run objdump on %v: %v", vmlinux, err) } close(allCoverReady) }() diff --git a/syz-manager/html.go b/syz-manager/html.go index f2d8b579..b096dd93 100644 --- a/syz-manager/html.go +++ b/syz-manager/html.go @@ -8,7 +8,6 @@ import ( "html/template" "io" "io/ioutil" - "log" "net" "net/http" _ "net/http/pprof" @@ -21,6 +20,7 @@ import ( "time" "github.com/google/syzkaller/cover" + . "github.com/google/syzkaller/log" "github.com/google/syzkaller/prog" "github.com/google/syzkaller/sys" ) @@ -37,12 +37,12 @@ func (mgr *Manager) initHttp() { ln, err := net.Listen("tcp4", mgr.cfg.Http) if err != nil { - fatalf("failed to listen on %v: %v", mgr.cfg.Http, err) + Fatalf("failed to listen on %v: %v", mgr.cfg.Http, err) } - logf(0, "serving http on http://%v", ln.Addr()) + Logf(0, "serving http on http://%v", ln.Addr()) go func() { err := http.Serve(ln, nil) - log.Fatalf("failed to serve http: %v", err) + Fatalf("failed to serve http: %v", err) }() } diff --git a/syz-manager/manager.go b/syz-manager/manager.go index ee09fe5f..75e47926 100644 --- a/syz-manager/manager.go +++ b/syz-manager/manager.go @@ -9,7 +9,6 @@ import ( "flag" "fmt" "io/ioutil" - "log" "net" "net/rpc" "net/rpc/jsonrpc" @@ -24,6 +23,7 @@ import ( "github.com/google/syzkaller/config" "github.com/google/syzkaller/cover" + . "github.com/google/syzkaller/log" "github.com/google/syzkaller/prog" "github.com/google/syzkaller/report" . "github.com/google/syzkaller/rpctype" @@ -38,7 +38,6 @@ import ( var ( flagConfig = flag.String("config", "", "configuration file") - flagV = flag.Int("v", 0, "verbosity") flagDebug = flag.Bool("debug", false, "dump all VM output to console") ) @@ -74,7 +73,7 @@ func main() { flag.Parse() cfg, syscalls, suppressions, err := config.Parse(*flagConfig) if err != nil { - fatalf("%v", err) + Fatalf("%v", err) } if *flagDebug { cfg.Debug = true @@ -95,7 +94,7 @@ func RunManager(cfg *config.Config, syscalls map[int]bool, suppressions []*regex fmt.Fprintf(buf, ",%v", c) } enabledSyscalls = buf.String()[1:] - logf(1, "enabled syscalls: %v", enabledSyscalls) + Logf(1, "enabled syscalls: %v", enabledSyscalls) } mgr := &Manager{ @@ -109,10 +108,10 @@ func RunManager(cfg *config.Config, syscalls map[int]bool, suppressions []*regex fuzzers: make(map[string]*Fuzzer), } - logf(0, "loading corpus...") + Logf(0, "loading corpus...") mgr.persistentCorpus = newPersistentSet(filepath.Join(cfg.Workdir, "corpus"), func(data []byte) bool { if _, err := prog.Deserialize(data); err != nil { - logf(0, "deleting broken program: %v\n%s", err, data) + Logf(0, "deleting broken program: %v\n%s", err, data) return false } return true @@ -120,7 +119,7 @@ func RunManager(cfg *config.Config, syscalls map[int]bool, suppressions []*regex for _, data := range mgr.persistentCorpus.a { p, err := prog.Deserialize(data) if err != nil { - fatalf("failed to deserialize program: %v", err) + Fatalf("failed to deserialize program: %v", err) } disabled := false for _, c := range p.Calls { @@ -139,7 +138,7 @@ func RunManager(cfg *config.Config, syscalls map[int]bool, suppressions []*regex } mgr.candidates = append(mgr.candidates, data) } - logf(0, "loaded %v programs", len(mgr.persistentCorpus.m)) + Logf(0, "loaded %v programs", len(mgr.persistentCorpus.m)) // Create HTTP server. mgr.initHttp() @@ -147,9 +146,9 @@ func RunManager(cfg *config.Config, syscalls map[int]bool, suppressions []*regex // Create RPC server for fuzzers. ln, err := net.Listen("tcp", cfg.Rpc) if err != nil { - fatalf("failed to listen on %v: %v", cfg.Rpc, err) + Fatalf("failed to listen on %v: %v", cfg.Rpc, err) } - logf(0, "serving rpc on tcp://%v", ln.Addr()) + Logf(0, "serving rpc on tcp://%v", ln.Addr()) mgr.port = ln.Addr().(*net.TCPAddr).Port s := rpc.NewServer() s.Register(mgr) @@ -157,14 +156,14 @@ func RunManager(cfg *config.Config, syscalls map[int]bool, suppressions []*regex for { conn, err := ln.Accept() if err != nil { - logf(0, "failed to accept an rpc connection: %v", err) + Logf(0, "failed to accept an rpc connection: %v", err) continue } go s.ServeCodec(jsonrpc.NewServerCodec(conn)) } }() - logf(0, "booting test machines...") + Logf(0, "booting test machines...") var shutdown uint32 var wg sync.WaitGroup wg.Add(cfg.Count + 1) @@ -178,7 +177,7 @@ func RunManager(cfg *config.Config, syscalls map[int]bool, suppressions []*regex break } if err != nil { - fatalf("failed to create VM config: %v", err) + Fatalf("failed to create VM config: %v", err) } ok := mgr.runInstance(vmCfg, i == 0) if atomic.LoadUint32(&shutdown) != 0 { @@ -198,7 +197,7 @@ func RunManager(cfg *config.Config, syscalls map[int]bool, suppressions []*regex executed := mgr.stats["exec total"] crashes := mgr.stats["crashes"] mgr.mu.Unlock() - logf(0, "executed programs: %v, crashes: %v", executed, crashes) + Logf(0, "executed programs: %v, crashes: %v", executed, crashes) } }() @@ -207,13 +206,13 @@ func RunManager(cfg *config.Config, syscalls map[int]bool, suppressions []*regex signal.Notify(c, syscall.SIGINT) <-c wg.Done() - *flagV = -1 // VMs will fail + DisableLog() // VMs will fail atomic.StoreUint32(&mgr.shutdown, 1) close(vm.Shutdown) - logf(-1, "shutting down...") + Logf(-1, "shutting down...") atomic.StoreUint32(&shutdown, 1) <-c - log.Fatalf("terminating") + Fatalf("terminating") }() wg.Wait() } @@ -221,24 +220,24 @@ func RunManager(cfg *config.Config, syscalls map[int]bool, suppressions []*regex func (mgr *Manager) runInstance(vmCfg *vm.Config, first bool) bool { inst, err := vm.Create(mgr.cfg.Type, vmCfg) if err != nil { - logf(0, "failed to create instance: %v", err) + Logf(0, "failed to create instance: %v", err) return false } defer inst.Close() fwdAddr, err := inst.Forward(mgr.port) if err != nil { - logf(0, "failed to setup port forwarding: %v", err) + Logf(0, "failed to setup port forwarding: %v", err) return false } fuzzerBin, err := inst.Copy(filepath.Join(mgr.cfg.Syzkaller, "bin", "syz-fuzzer")) if err != nil { - logf(0, "failed to copy binary: %v", err) + Logf(0, "failed to copy binary: %v", err) return false } executorBin, err := inst.Copy(filepath.Join(mgr.cfg.Syzkaller, "bin", "syz-executor")) if err != nil { - logf(0, "failed to copy binary: %v", err) + Logf(0, "failed to copy binary: %v", err) return false } @@ -254,14 +253,14 @@ func (mgr *Manager) runInstance(vmCfg *vm.Config, first bool) bool { "%v -executor=%v -name=%v -manager=%v -output=%v -procs=%v -leak=%v -cover=%v -sandbox=%v -debug=%v -v=%d", fuzzerBin, executorBin, vmCfg.Name, fwdAddr, mgr.cfg.Output, mgr.cfg.Procs, leak, mgr.cfg.Cover, mgr.cfg.Sandbox, *flagDebug, fuzzerV)) if err != nil { - logf(0, "failed to run fuzzer: %v", err) + Logf(0, "failed to run fuzzer: %v", err) return false } desc, text, output, crashed, timedout := vm.MonitorExecution(outc, errc, mgr.cfg.Type == "local", true) if timedout { // This is the only "OK" outcome. - logf(0, "%v: running long enough, restarting", vmCfg.Name) + Logf(0, "%v: running long enough, restarting", vmCfg.Name) } else { if !crashed { // syz-fuzzer exited, but it should not. @@ -280,7 +279,7 @@ func (mgr *Manager) saveCrasher(vmCfg *vm.Config, desc string, text, output []by } for _, re := range mgr.suppressions { if re.Match(output) { - logf(1, "%v: suppressing '%v' with '%v'", vmCfg.Name, desc, re.String()) + Logf(1, "%v: suppressing '%v' with '%v'", vmCfg.Name, desc, re.String()) mgr.mu.Lock() mgr.stats["suppressed"]++ mgr.mu.Unlock() @@ -288,7 +287,7 @@ func (mgr *Manager) saveCrasher(vmCfg *vm.Config, desc string, text, output []by } } - logf(0, "%v: crash: %v", vmCfg.Name, desc) + Logf(0, "%v: crash: %v", vmCfg.Name, desc) mgr.mu.Lock() mgr.stats["crashes"]++ mgr.mu.Unlock() @@ -298,7 +297,7 @@ func (mgr *Manager) saveCrasher(vmCfg *vm.Config, desc string, text, output []by dir := filepath.Join(mgr.crashdir, id) os.MkdirAll(dir, 0700) if err := ioutil.WriteFile(filepath.Join(dir, "description"), []byte(desc+"\n"), 0660); err != nil { - logf(0, "failed to write crash: %v", err) + Logf(0, "failed to write crash: %v", err) } // Save up to 100 reports. If we already have 100, overwrite the oldest one. // Newer reports are generally more useful. Overwriting is also needed @@ -323,7 +322,7 @@ func (mgr *Manager) saveCrasher(vmCfg *vm.Config, desc string, text, output []by if len(text) > 0 { symbolized, err := report.Symbolize(mgr.cfg.Vmlinux, text) if err != nil { - logf(0, "failed to symbolize crash: %v", err) + Logf(0, "failed to symbolize crash: %v", err) } else { text = symbolized } @@ -352,7 +351,7 @@ func (mgr *Manager) minimizeCorpus() { newCorpus = append(newCorpus, c.inputs[idx]) } } - logf(1, "minimized corpus: %v -> %v", len(mgr.corpus), len(newCorpus)) + Logf(1, "minimized corpus: %v -> %v", len(mgr.corpus), len(newCorpus)) mgr.corpus = newCorpus } var corpus []*prog.Prog @@ -380,7 +379,7 @@ func (mgr *Manager) minimizeCorpus() { } func (mgr *Manager) Connect(a *ConnectArgs, r *ConnectRes) error { - logf(1, "fuzzer %v connected", a.Name) + Logf(1, "fuzzer %v connected", a.Name) mgr.mu.Lock() defer mgr.mu.Unlock() @@ -401,7 +400,7 @@ func (mgr *Manager) Connect(a *ConnectArgs, r *ConnectRes) error { } func (mgr *Manager) NewInput(a *NewInputArgs, r *int) error { - logf(2, "new input from %v for syscall %v", a.Name, a.Call) + Logf(2, "new input from %v for syscall %v", a.Name, a.Call) mgr.mu.Lock() defer mgr.mu.Unlock() @@ -417,7 +416,7 @@ func (mgr *Manager) NewInput(a *NewInputArgs, r *int) error { } func (mgr *Manager) Poll(a *PollArgs, r *PollRes) error { - logf(2, "poll from %v", a.Name) + Logf(2, "poll from %v", a.Name) mgr.mu.Lock() defer mgr.mu.Unlock() @@ -427,7 +426,7 @@ func (mgr *Manager) Poll(a *PollArgs, r *PollRes) error { f := mgr.fuzzers[a.Name] if f == nil { - fatalf("fuzzer %v is not connected", a.Name) + Fatalf("fuzzer %v is not connected", a.Name) } for i := 0; i < 100 && f.input < len(mgr.corpus); i++ { @@ -446,13 +445,3 @@ func (mgr *Manager) Poll(a *PollArgs, r *PollRes) error { return nil } - -func logf(v int, msg string, args ...interface{}) { - if *flagV >= v { - log.Printf(msg, args...) - } -} - -func fatalf(msg string, args ...interface{}) { - log.Fatalf(msg, args...) -} diff --git a/syz-manager/persistent.go b/syz-manager/persistent.go index b656a76f..5839027a 100644 --- a/syz-manager/persistent.go +++ b/syz-manager/persistent.go @@ -8,9 +8,10 @@ import ( "encoding/hex" "fmt" "io/ioutil" - "log" "os" "path/filepath" + + . "github.com/google/syzkaller/log" ) type Sig [sha1.Size]byte @@ -34,7 +35,7 @@ func newPersistentSet(dir string, verify func(data []byte) bool) *PersistentSet os.MkdirAll(dir, 0770) filepath.Walk(dir, func(path string, info os.FileInfo, err error) error { if err != nil { - log.Fatalf("error during dir walk: %v\n", err) + Fatalf("error during dir walk: %v\n", err) } if info.IsDir() { if info.Name() == ".git" { @@ -44,7 +45,7 @@ func newPersistentSet(dir string, verify func(data []byte) bool) *PersistentSet } data, err := ioutil.ReadFile(path) if err != nil { - log.Fatalf("error during file read: %v\n", err) + Fatalf("error during file read: %v\n", err) return nil } sig := hash(data) @@ -55,7 +56,7 @@ func newPersistentSet(dir string, verify func(data []byte) bool) *PersistentSet if len(data) == 0 { // This can happen is master runs on machine-under-test, // and it has crashed midway. - log.Printf("removing empty file %v", name) + Logf(0, "removing empty file %v", name) os.Remove(path) return nil } @@ -64,16 +65,16 @@ func newPersistentSet(dir string, verify func(data []byte) bool) *PersistentSet return nil // description file } if len(name) != hexLen || !isHexString(name) { - log.Fatalf("unknown file in persistent dir %v: %v", dir, name) + Logf(0, "unknown file in persistent dir %v: %v", dir, name) } if verify != nil && !verify(data) { os.Remove(path) return nil } if name != hex.EncodeToString(sig[:]) { - log.Printf("bad hash in persistent dir %v for file %v, expect %v", dir, name, hex.EncodeToString(sig[:])) + Logf(0, "bad hash in persistent dir %v for file %v, expect %v", dir, name, hex.EncodeToString(sig[:])) if err := ioutil.WriteFile(filepath.Join(ps.dir, hex.EncodeToString(sig[:])), data, 0660); err != nil { - log.Fatalf("failed to write file: %v", err) + Fatalf("failed to write file: %v", err) } os.Remove(path) } @@ -103,7 +104,7 @@ func (ps *PersistentSet) add(data []byte) bool { ps.a = append(ps.a, data) fname := filepath.Join(ps.dir, hex.EncodeToString(sig[:])) if err := ioutil.WriteFile(fname, data, 0660); err != nil { - log.Fatalf("failed to write file: %v", err) + Fatalf("failed to write file: %v", err) } return true } @@ -113,7 +114,7 @@ func (ps *PersistentSet) addDescription(data []byte, desc []byte, typ string) { sig := hash(data) fname := filepath.Join(ps.dir, fmt.Sprintf("%v.%v", hex.EncodeToString(sig[:]), typ)) if err := ioutil.WriteFile(fname, desc, 0660); err != nil { - log.Fatalf("failed to write file: %v", err) + Fatalf("failed to write file: %v", err) } } diff --git a/tools/syz-execprog/execprog.go b/tools/syz-execprog/execprog.go index d331c4e5..48a686e7 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 de685acc..27e6c1cd 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 0507f0f5..12665f66 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...) -} diff --git a/vm/adb/adb.go b/vm/adb/adb.go index c428df3a..65cf60d0 100644 --- a/vm/adb/adb.go +++ b/vm/adb/adb.go @@ -7,7 +7,6 @@ import ( "fmt" "io" "io/ioutil" - "log" "os" "os/exec" "path/filepath" @@ -15,6 +14,7 @@ import ( "sync" "time" + . "github.com/google/syzkaller/log" "github.com/google/syzkaller/vm" ) @@ -99,7 +99,7 @@ func (inst *instance) findConsole() error { } inst.console = "/dev/" + filepath.Base(files[0]) consoleCache[inst.cfg.Device] = inst.console - log.Printf("associating adb device %v with console %v", inst.cfg.Device, inst.console) + Logf(0, "associating adb device %v with console %v", inst.cfg.Device, inst.console) return nil } @@ -114,7 +114,7 @@ func (inst *instance) Forward(port int) (string, error) { func (inst *instance) adb(args ...string) ([]byte, error) { if inst.cfg.Debug { - log.Printf("executing adb %+v", args) + Logf(0, "executing adb %+v", args) } rpipe, wpipe, err := os.Pipe() if err != nil { @@ -134,7 +134,7 @@ func (inst *instance) adb(args ...string) ([]byte, error) { select { case <-time.After(time.Minute): if inst.cfg.Debug { - log.Printf("adb hanged") + Logf(0, "adb hanged") } cmd.Process.Kill() case <-done: @@ -144,13 +144,13 @@ func (inst *instance) adb(args ...string) ([]byte, error) { close(done) out, _ := ioutil.ReadAll(rpipe) if inst.cfg.Debug { - log.Printf("adb failed: %v\n%s", err, out) + Logf(0, "adb failed: %v\n%s", err, out) } return nil, fmt.Errorf("adb %+v failed: %v\n%s", args, err, out) } close(done) if inst.cfg.Debug { - log.Printf("adb returned") + Logf(0, "adb returned") } out, _ := ioutil.ReadAll(rpipe) return out, nil @@ -199,11 +199,11 @@ func (inst *instance) checkBatteryLevel() error { return err } if val >= minLevel { - log.Printf("device %v: battery level %v%%, OK", inst.cfg.Device, val) + Logf(0, "device %v: battery level %v%%, OK", inst.cfg.Device, val) return nil } for { - log.Printf("device %v: battery level %v%%, waiting for %v%%", inst.cfg.Device, val, requiredLevel) + Logf(0, "device %v: battery level %v%%, waiting for %v%%", inst.cfg.Device, val, requiredLevel) if !vm.SleepInterruptible(time.Minute) { return nil } @@ -272,7 +272,7 @@ func (inst *instance) Run(timeout time.Duration, command string) (<-chan []byte, go func() { err := cat.Wait() if inst.cfg.Debug { - log.Printf("cat exited: %v", err) + Logf(0, "cat exited: %v", err) } catDone <- fmt.Errorf("cat exited: %v", err) }() @@ -284,7 +284,7 @@ func (inst *instance) Run(timeout time.Duration, command string) (<-chan []byte, return nil, nil, err } if inst.cfg.Debug { - log.Printf("starting: adb shell %v", command) + Logf(0, "starting: adb shell %v", command) } adb := exec.Command(inst.cfg.Bin, "-s", inst.cfg.Device, "shell", "cd /data; "+command) adb.Stdout = adbWpipe @@ -301,7 +301,7 @@ func (inst *instance) Run(timeout time.Duration, command string) (<-chan []byte, go func() { err := adb.Wait() if inst.cfg.Debug { - log.Printf("adb exited: %v", err) + Logf(0, "adb exited: %v", err) } adbDone <- fmt.Errorf("adb exited: %v", err) }() @@ -330,7 +330,7 @@ func (inst *instance) Run(timeout time.Duration, command string) (<-chan []byte, adb.Process.Kill() case <-inst.closed: if inst.cfg.Debug { - log.Printf("instance closed") + Logf(0, "instance closed") } signal(fmt.Errorf("instance closed")) cat.Process.Kill() diff --git a/vm/gce/gce.go b/vm/gce/gce.go index 524ab1c3..8cb9b534 100644 --- a/vm/gce/gce.go +++ b/vm/gce/gce.go @@ -14,7 +14,6 @@ package gce import ( "fmt" "io/ioutil" - "log" "os" "os/exec" "path/filepath" @@ -22,6 +21,7 @@ import ( "time" "github.com/google/syzkaller/gce" + . "github.com/google/syzkaller/log" "github.com/google/syzkaller/vm" ) @@ -48,9 +48,9 @@ func initGCE() { var err error GCE, err = gce.NewContext() if err != nil { - log.Fatalf("failed to init gce: %v", err) + Fatalf("failed to init gce: %v", err) } - log.Printf("gce initialized: running on %v, internal IP, %v project %v, zone %v", GCE.Instance, GCE.InternalIP, GCE.ProjectID, GCE.ZoneID) + Logf(0, "gce initialized: running on %v, internal IP, %v project %v, zone %v", GCE.Instance, GCE.InternalIP, GCE.ProjectID, GCE.ZoneID) } func ctor(cfg *vm.Config) (vm.Instance, error) { @@ -74,11 +74,11 @@ func ctor(cfg *vm.Config) (vm.Instance, error) { return nil, fmt.Errorf("failed to read file: %v", err) } - log.Printf("deleting instance: %v", name) + Logf(0, "deleting instance: %v", name) if err := GCE.DeleteInstance(name); err != nil { return nil, err } - log.Printf("creating instance: %v", name) + Logf(0, "creating instance: %v", name) ip, err := GCE.CreateInstance(name, cfg.MachineType, cfg.Image, string(sshkeyPub)) if err != nil { return nil, err @@ -88,7 +88,7 @@ func ctor(cfg *vm.Config) (vm.Instance, error) { GCE.DeleteInstance(name) } }() - log.Printf("wait instance to boot: %v (%v)", name, ip) + Logf(0, "wait instance to boot: %v (%v)", name, ip) if err := waitInstanceBoot(ip, cfg.Sshkey); err != nil { return nil, err }