Add debug logging to sysgen/ code

4 files changed, 40 insertions, 4 deletions

diff --git a/README.md b/README.md
index 76ec1bc99..b6f97296d 100644
--- a/README.md
+++ b/README.md
@@ -230,6 +230,9 @@ This will re-create the following source code files:
    (per-architecture) kernel syscall numbers.
  - `executor/syscalls.h`: Constant definitions (in C) for all system call numbers.
 
+If there are problems with this step, run `bin/syz-sysgen` directly and add
+the use `-v=5` flag to show more details of the generation process.
+
 Rebuild syzkaller (`make clean all`) to force use of the new system call definitions.
 
 Finally, adjust the `enable_syscalls` configuration value for syzkaller to specifically target the
diff --git a/sysgen/fetch.go b/sysgen/fetch.go
index 0c43d3d7d..941c6d587 100644
--- a/sysgen/fetch.go
+++ b/sysgen/fetch.go
@@ -16,6 +16,7 @@ import (
 // into their respective numeric values. It does so by builting and executing a C program
 // that prints values of the provided expressions.
 func fetchValues(arch string, vals []string, includes []string, defines map[string]string) []string {
+	logf(1, "Use C compiler to fetch constant values for arch=%v", arch)
 	includeText := ""
 	for _, inc := range includes {
 		includeText += fmt.Sprintf("#include <%v>\n", inc)
@@ -33,6 +34,7 @@ func fetchValues(arch string, vals []string, includes []string, defines map[stri
 	}
 	bin.Close()
 	defer os.Remove(bin.Name())
+	logf(2, "  Build C program into temp file %v", bin.Name())
 
 	args := []string{"-x", "c", "-", "-o", bin.Name()}
 	args = append(args, []string{
@@ -55,6 +57,8 @@ func fetchValues(arch string, vals []string, includes []string, defines map[stri
 		"-include", *flagLinux + "/include/linux/kconfig.h",
 	}...)
 
+	logf(4, "  Source code:\n%v", src)
+	logf(2, "  Execute gcc with: %v", args)
 	cmd := exec.Command("gcc", args...)
 	cmd.Stdin = strings.NewReader(src)
 	out, err := cmd.CombinedOutput()
diff --git a/sysgen/syscallnr.go b/sysgen/syscallnr.go
index 7e8131762..124ccc697 100644
--- a/sysgen/syscallnr.go
+++ b/sysgen/syscallnr.go
@@ -61,11 +61,13 @@ func fetchSyscallsNumbers(arch *Arch, syscalls []Syscall) {
 }
 
 func generateSyscallsNumbersArch(arch *Arch, syscalls []Syscall) {
+	var archcode string = "sys/sys_"+arch.GOARCH+".go"
+	logf(1, "Generate code with syscall numbers for arch=%v in %v", arch.GOARCH, archcode)
 	buf := new(bytes.Buffer)
 	if err := archTempl.Execute(buf, arch); err != nil {
 		failf("failed to execute arch template: %v", err)
 	}
-	writeSource("sys/sys_"+arch.GOARCH+".go", buf.Bytes())
+	writeSource(archcode, buf.Bytes())
 }
 
 func generateExecutorSyscalls(syscalls []Syscall) {
@@ -82,11 +84,13 @@ func generateExecutorSyscalls(syscalls []Syscall) {
 	}
 	sort.Sort(SyscallArray(data.FakeCalls))
 
+	var hdrcode string = "executor/syscalls.h"
+	logf(1, "Generate header with syscall numbers in %v", hdrcode)
 	buf := new(bytes.Buffer)
 	if err := syscallsTempl.Execute(buf, data); err != nil {
 		failf("failed to execute syscalls template: %v", err)
 	}
-	writeFile("executor/syscalls.h", buf.Bytes())
+	writeFile(hdrcode, buf.Bytes())
 }
 
 type SyscallsData struct {
diff --git a/sysgen/sysgen.go b/sysgen/sysgen.go
index f52e12ab7..4fbb31755 100644
--- a/sysgen/sysgen.go
+++ b/sysgen/sysgen.go
@@ -10,6 +10,7 @@ import (
 	"fmt"
 	"go/format"
 	"io"
+	"log"
 	"os"
 	"sort"
 	"strconv"
@@ -19,6 +20,7 @@ import (
 var (
 	flagLinux = flag.String("linux", "", "path to linux kernel source checkout")
 	flagLinuxBld = flag.String("linuxbld", "", "path to linux kernel build directory")
+	flagV = flag.Int("v", 0, "verbosity")
 )
 
 func main() {
@@ -27,6 +29,7 @@ func main() {
 		failf("provide path to linux kernel checkout via -linux flag (or make generate LINUX= flag)")
 	}
 	if *flagLinuxBld == "" {
+		logf(1, "No kernel build directory provided, assuming in-place build")
 		flagLinuxBld = flagLinux
 	}
 	if len(flag.Args()) == 0 {
@@ -36,6 +39,7 @@ func main() {
 	var r io.Reader
 	for i, f := range flag.Args() {
 		inf, err := os.Open(f)
+		logf(1, "Load descriptions from file %v", f)
 		if err != nil {
 			failf("failed to open input file: %v", err)
 		}
@@ -47,16 +51,22 @@ func main() {
 		}
 	}
 
+	logf(1, "Parse system call descriptions")
 	includes, defines, syscalls, structs, unnamed, flags := parse(r)
+	logf(1, "Build flag definitions")
 	intFlags, flagVals := compileFlags(includes, defines, flags)
 
+	var initcode string = "sys/sys.go"
+	logf(1, "Generate code to init system call data in %v", initcode)
 	out := new(bytes.Buffer)
 	generate(syscalls, structs, unnamed, intFlags, flagVals, out)
-	writeSource("sys/sys.go", out.Bytes())
+	writeSource(initcode, out.Bytes())
 
+	var constcode string = "prog/consts.go"
+	logf(1, "Generate code for constant values in %v", constcode)
 	out = new(bytes.Buffer)
 	generateConsts(flagVals, out)
-	writeSource("prog/consts.go", out.Bytes())
+	writeSource(constcode, out.Bytes())
 
 	generateSyscallsNumbers(syscalls)
 }
@@ -84,6 +94,7 @@ func generate(syscalls []Syscall, structs map[string]Struct, unnamed map[string]
 	fmt.Fprintf(out, "var Calls []*Call\n")
 	fmt.Fprintf(out, "func initCalls() {\n")
 	for i, s := range syscalls {
+		logf(4, "    generate population code for %v", s.Name)
 		fmt.Fprintf(out, "func() { Calls = append(Calls, &Call{ID: %v, Name: \"%v\", CallName: \"%v\"", i, s.Name, s.CallName)
 		if len(s.Ret) != 0 {
 			fmt.Fprintf(out, ", Ret: ")
@@ -94,6 +105,7 @@ func generate(syscalls []Syscall, structs map[string]Struct, unnamed map[string]
 			if i != 0 {
 				fmt.Fprintf(out, ", ")
 			}
+			logf(5, "      generate description for arg %v", i)
 			generateArg(a[0], a[1], a[2:], structs, unnamed, flags, flagVals, false, out)
 		}
 		fmt.Fprintf(out, "}})}()\n")
@@ -627,11 +639,13 @@ func parse(in io.Reader) (includes []string, defines map[string]string, syscalls
 						}
 					}
 				}
+				logf(2, "  Add struct %v", str.Name)
 				structs[str.Name] = *str
 				str = nil
 			} else {
 				p.SkipWs()
 				fld := []string{p.Ident()}
+				logf(3, "    Add field %f to struct %v", fld, str.Name)
 				fld = append(fld, parseType(p, unnamed, flags)...)
 				str.Flds = append(str.Flds, fld)
 			}
@@ -649,6 +663,7 @@ func parse(in io.Reader) (includes []string, defines map[string]string, syscalls
 					include = append(include, ch)
 				}
 				p.Parse('>')
+				logf(2, "  Add #include file %v", string(include))
 				includes = append(includes, string(include))
 			} else if name == "define" {
 				key := p.Ident()
@@ -661,6 +676,7 @@ func parse(in io.Reader) (includes []string, defines map[string]string, syscalls
 				if defines[key] != "" {
 					failf("%v define is defined multiple times", key)
 				}
+				logf(2, "  Add #define %v %v", key, val)
 				defines[key] = fmt.Sprintf("(%s)", val)
 			} else {
 				switch ch := p.Char(); ch {
@@ -685,6 +701,7 @@ func parse(in io.Reader) (includes []string, defines map[string]string, syscalls
 					if idx := strings.IndexByte(callName, '$'); idx != -1 {
 						callName = callName[:idx]
 					}
+					logf(2, "  Add system call %v", name)
 					syscalls = append(syscalls, Syscall{name, callName, args, ret})
 				case '=':
 					// flag
@@ -694,6 +711,7 @@ func parse(in io.Reader) (includes []string, defines map[string]string, syscalls
 						p.Parse(',')
 						vals = append(vals, p.Ident())
 					}
+					logf(2, "  Add flag %v", name)
 					flags[name] = vals
 				case '{', '[':
 					p.Parse(ch)
@@ -779,3 +797,10 @@ func failf(msg string, args ...interface{}) {
 	fmt.Fprintf(os.Stderr, msg+"\n", args...)
 	os.Exit(1)
 }
+
+func logf(v int, msg string, args ...interface{}) {
+	if *flagV >= v {
+		log.Printf(msg, args...)
+	}
+}
+