pkg/report: support CONFIG_PRINTK_CALLER

CONFIG_PRINTK_CALLER has reached linux-next:
https://groups.google.com/d/msg/syzkaller/xEDUgkgFvL8/d5bBS3BJBwAJ

Enable CONFIG_PRINTK_CALLER and support parsing of its output format.

This gives us several advantages:
 - output from different contexts don't intermix
 - intermixed output doesn't cause corrupted reports
 - we can keep larger prefix since we know it comes from the same task

Credit for the kernel part goes to Tetsuo Handa.
Also Sergey Senozhatsky and Petr Mladek for reviews of the kernel part.

Fixes #596
Fixes #600

dashboard/config/upstream-kasan.config

@@ -1,6 +1,6 @@
 #
 # Automatically generated file; DO NOT EDIT.
-# Linux/x86 4.20.0-rc7 Kernel Configuration
+# Linux/x86 4.20.0 Kernel Configuration
 #
 
 # The following configs are added manually, preserve them.
@@ -14,10 +14,10 @@ CONFIG_DEBUG_MEMORY=y
 CONFIG_DEBUG_AID_FOR_SYZBOT=y
 
 #
-# Compiler: gcc (GCC) 8.0.1 20180412 (experimental)
+# Compiler: gcc (GCC) 9.0.0 20181231 (experimental)
 #
 CONFIG_CC_IS_GCC=y
-CONFIG_GCC_VERSION=80001
+CONFIG_GCC_VERSION=90000
 CONFIG_CLANG_VERSION=0
 CONFIG_CONSTRUCTORS=y
 CONFIG_IRQ_WORK=y
@@ -182,8 +182,8 @@ CONFIG_RD_LZO=y
 CONFIG_RD_LZ4=y
 CONFIG_CC_OPTIMIZE_FOR_PERFORMANCE=y
 # CONFIG_CC_OPTIMIZE_FOR_SIZE is not set
-# CONFIG_CC_OPTIMIZE_FOR_DEBUGGING is not set
 CONFIG_SYSCTL=y
+CONFIG_ANON_INODES=y
 CONFIG_HAVE_UID16=y
 CONFIG_SYSCTL_EXCEPTION_TRACE=y
 CONFIG_HAVE_PCSPKR_PLATFORM=y
@@ -421,6 +421,7 @@ CONFIG_ARCH_USES_PG_UNCACHED=y
 CONFIG_ARCH_RANDOM=y
 CONFIG_X86_SMAP=y
 # CONFIG_X86_INTEL_UMIP is not set
+CONFIG_X86_INTEL_MPX=y
 CONFIG_X86_INTEL_MEMORY_PROTECTION_KEYS=y
 CONFIG_EFI=y
 # CONFIG_EFI_STUB is not set
@@ -1863,6 +1864,7 @@ CONFIG_HOTPLUG_PCI=y
 #
 # CONFIG_PCIE_DW_PLAT_HOST is not set
 # CONFIG_PCIE_DW_PLAT_EP is not set
+# CONFIG_PCI_MESON is not set
 
 #
 # PCI Endpoint
@@ -3532,6 +3534,7 @@ CONFIG_ITCO_VENDOR_SUPPORT=y
 # CONFIG_CPU5_WDT is not set
 # CONFIG_SMSC_SCH311X_WDT is not set
 # CONFIG_SMSC37B787_WDT is not set
+# CONFIG_TQMX86_WDT is not set
 # CONFIG_VIA_WDT is not set
 # CONFIG_W83627HF_WDT is not set
 # CONFIG_W83877F_WDT is not set
@@ -5681,6 +5684,7 @@ CONFIG_CRYPTO_OFB=y
 CONFIG_CRYPTO_PCBC=y
 CONFIG_CRYPTO_XTS=y
 CONFIG_CRYPTO_KEYWRAP=y
+CONFIG_CRYPTO_NHPOLY1305=y
 CONFIG_CRYPTO_NHPOLY1305_SSE2=y
 CONFIG_CRYPTO_NHPOLY1305_AVX2=y
 CONFIG_CRYPTO_ADIANTUM=y
@@ -5943,7 +5947,7 @@ CONFIG_SBITMAP=y
 # printk and dmesg options
 #
 CONFIG_PRINTK_TIME=y
-# CONFIG_PRINTK_CALLER is not set
+CONFIG_PRINTK_CALLER=y
 CONFIG_CONSOLE_LOGLEVEL_DEFAULT=7
 CONFIG_CONSOLE_LOGLEVEL_QUIET=4
 CONFIG_MESSAGE_LOGLEVEL_DEFAULT=4
@@ -5958,7 +5962,6 @@ CONFIG_DEBUG_INFO=y
 # CONFIG_DEBUG_INFO_SPLIT is not set
 # CONFIG_DEBUG_INFO_DWARF4 is not set
 # CONFIG_GDB_SCRIPTS is not set
-# CONFIG_NO_AUTO_INLINE is not set
 CONFIG_ENABLE_MUST_CHECK=y
 CONFIG_FRAME_WARN=2048
 # CONFIG_STRIP_ASM_SYMS is not set

pkg/report/freebsd.go

@@ -43,14 +43,12 @@ func (ctx *freebsd) Parse(output []byte) *Report {
 			next = len(output)
 		}
 		for _, oops1 := range freebsdOopses {
-			match := matchOops(output[pos:next], oops1, ctx.ignores)
-			if match == -1 {
+			if !matchOops(output[pos:next], oops1, ctx.ignores) {
 				continue
 			}
 			if oops == nil {
 				oops = oops1
 				rep.StartPos = pos
-				rep.Title = string(output[pos+match : next])
 			}
 			rep.EndPos = next
 		}

pkg/report/linux.go

@@ -27,6 +27,7 @@ type linux struct {
 	ignores               []*regexp.Regexp
 	consoleOutputRe       *regexp.Regexp
 	questionableRe        *regexp.Regexp
+	taskContext           *regexp.Regexp
 	guiltyFileBlacklist   []*regexp.Regexp
 	reportStartIgnores    []*regexp.Regexp
 	infoMessagesWithStack [][]byte
@@ -51,8 +52,9 @@ func ctorLinux(target *targets.Target, kernelSrc, kernelObj string, ignores []*r
 		symbols:   symbols,
 		ignores:   ignores,
 	}
-	ctx.consoleOutputRe = regexp.MustCompile(`^(?:\*\* [0-9]+ printk messages dropped \*\* )?(?:.* login: )?(?:\<[0-9]+\>)?\[ *[0-9]+\.[0-9]+\] `)
-	ctx.questionableRe = regexp.MustCompile(`(?:\[\<[0-9a-f]+\>\])? \? +[a-zA-Z0-9_.]+\+0x[0-9a-f]+/[0-9a-f]+`)
+	ctx.consoleOutputRe = regexp.MustCompile(`^(?:\*\* [0-9]+ printk messages dropped \*\* )?(?:.* login: )?(?:\<[0-9]+\>)?\[ *[0-9]+\.[0-9]+\](\[ *(?:C|T)[0-9]+\])? `)
+	ctx.questionableRe = regexp.MustCompile(`(\[\<[0-9a-f]+\>\])? \? +[a-zA-Z0-9_.]+\+0x[0-9a-f]+/[0-9a-f]+`)
+	ctx.taskContext = regexp.MustCompile(`\[ *T[0-9]+\]`)
 	ctx.eoi = []byte("<EOI>")
 	ctx.guiltyFileBlacklist = []*regexp.Regexp{
 		regexp.MustCompile(`.*\.h`),
@@ -126,42 +128,31 @@ func (ctx *linux) ContainsCrash(output []byte) bool {
 }
 
 func (ctx *linux) Parse(output []byte) *Report {
-	oops, startPos, endPos, logReport, consoleReport, consoleReportReliable,
-		logReportPrefix, consoleReportPrefix := ctx.parseOutput(output)
+	oops, startPos, context := ctx.findFirstOops(output)
 	if oops == nil {
 		return nil
 	}
 	rep := &Report{
 		Output:   output,
 		StartPos: startPos,
-		EndPos:   endPos,
 	}
-	var report []byte
-	var reportPrefix [][]byte
-	// Try extracting report from console output only.
-	title, corrupted, format := extractDescription(consoleReportReliable, oops, linuxStackParams)
-	if title != "" {
-		report = consoleReport
-		reportPrefix = consoleReportPrefix
-	} else {
-		// Failure. Try extracting report from the whole log.
-		report = logReport
-		reportPrefix = logReportPrefix
+	endPos, reportEnd, report, prefix := ctx.findReport(output, oops, startPos, context)
+	rep.EndPos = endPos
+	title, corrupted, format := extractDescription(report[:reportEnd], oops, linuxStackParams)
+	if title == "" {
+		prefix = nil
+		report = output[rep.StartPos:rep.EndPos]
 		title, corrupted, format = extractDescription(report, oops, linuxStackParams)
 		if title == "" {
-			panic(fmt.Sprintf("non matching oops for %q in:\n%s\n\nconsole:\n%s\n"+
-				"output [range:%v-%v]:\n%s\n",
-				oops.header, report, consoleReportReliable,
-				rep.StartPos, rep.StartPos+len(report), output))
+			panic(fmt.Sprintf("non matching oops for %q context=%q in:\n%s\n",
+				oops.header, context, report))
 		}
 	}
 	rep.Title = title
 	rep.Corrupted = corrupted != ""
 	rep.CorruptedReason = corrupted
-	// Prepend 5 lines preceding start of the report,
-	// they can contain additional info related to the report.
-	for _, prefix := range reportPrefix {
-		rep.Report = append(rep.Report, prefix...)
+	for _, line := range prefix {
+		rep.Report = append(rep.Report, line...)
 		rep.Report = append(rep.Report, '\n')
 	}
 	rep.reportPrefixLen = len(rep.Report)
@@ -172,28 +163,67 @@ func (ctx *linux) Parse(output []byte) *Report {
 	return rep
 }
 
+func (ctx *linux) findFirstOops(output []byte) (oops *oops, startPos int, context string) {
+	for pos, next := 0, 0; pos < len(output); pos = next + 1 {
+		next = bytes.IndexByte(output[pos:], '\n')
+		if next != -1 {
+			next += pos
+		} else {
+			next = len(output)
+		}
+		line := output[pos:next]
+		for _, oops1 := range linuxOopses {
+			if matchOops(line, oops1, ctx.ignores) {
+				oops = oops1
+				startPos = pos
+				context = ctx.extractContext(line)
+
+				//stripped, questionable := ctx.stripLinePrefix(line, context1)
+
+				return
+			}
+		}
+	}
+	return
+}
+
 // Yes, it is complex, but all state and logic are tightly coupled. It's unclear how to simplify it.
 // nolint: gocyclo
-func (ctx *linux) parseOutput(output []byte) (
-	oops *oops, startPos, endPos int,
-	logReport, consoleReport, consoleReportReliable []byte,
-	logReportPrefix, consoleReportPrefix [][]byte) {
-	firstReportEnd := 0
+func (ctx *linux) findReport(output []byte, oops *oops, startPos int, context string) (
+	endPos, reportEnd int, report []byte, prefix [][]byte) {
+	// Prepend 5 lines preceding start of the report,
+	// they can contain additional info related to the report.
+	maxPrefix := 5
+	if ctx.taskContext.MatchString(context) {
+		// If we have CONFIG_PRINTK_CALLER, we collect more b/c it comes from the same task.
+		maxPrefix = 50
+	}
 	secondReportPos := 0
 	textLines := 0
 	skipText := false
-	for pos := 0; pos < len(output); {
-		next := bytes.IndexByte(output[pos:], '\n')
+	for pos, next := 0, 0; pos < len(output); pos = next + 1 {
+		next = bytes.IndexByte(output[pos:], '\n')
 		if next != -1 {
 			next += pos
 		} else {
 			next = len(output)
 		}
 		line := output[pos:next]
+		context1 := ctx.extractContext(line)
+		stripped, questionable := ctx.stripLinePrefix(line, context1)
+		if pos < startPos {
+			if context1 == context && len(stripped) != 0 && !questionable {
+				prefix = append(prefix, append([]byte{}, stripped...))
+				if len(prefix) > maxPrefix {
+					prefix = prefix[1:]
+				}
+			}
+			continue
+		}
+		oopsLine := pos == startPos
 		for _, oops1 := range linuxOopses {
-			match := matchOops(line, oops1, ctx.ignores)
-			if match == -1 {
-				if oops != nil && secondReportPos == 0 {
+			if !matchOops(line, oops1, ctx.ignores) {
+				if !oopsLine && secondReportPos == 0 {
 					for _, pattern := range ctx.infoMessagesWithStack {
 						if bytes.Contains(line, pattern) {
 							secondReportPos = pos
@@ -204,75 +234,66 @@ func (ctx *linux) parseOutput(output []byte) (
 				continue
 			}
 			endPos = next
-			if oops == nil {
-				oops = oops1
-				startPos = pos
-				break
-			} else if secondReportPos == 0 {
+			if !oopsLine && secondReportPos == 0 {
 				if !matchesAny(line, ctx.reportStartIgnores) {
 					secondReportPos = pos
 				}
 			}
 		}
-		if oops == nil {
-			logReportPrefix = append(logReportPrefix, append([]byte{}, line...))
-			if len(logReportPrefix) > 5 {
-				logReportPrefix = logReportPrefix[1:]
-			}
+		if !oopsLine && (context1 != context || questionable) {
+			continue
 		}
-		if ctx.consoleOutputRe.Match(line) &&
-			(!ctx.questionableRe.Match(line) || bytes.Contains(line, ctx.eoi)) {
-			lineStart := bytes.Index(line, []byte("] ")) + pos + 2
-			lineEnd := next
-			if lineEnd != 0 && output[lineEnd-1] == '\r' {
-				lineEnd--
-			}
-			if oops == nil {
-				consoleReportPrefix = append(consoleReportPrefix,
-					append([]byte{}, output[lineStart:lineEnd]...))
-				if len(consoleReportPrefix) > 5 {
-					consoleReportPrefix = consoleReportPrefix[1:]
-				}
-			} else {
-				textLines++
-				ln := output[lineStart:lineEnd]
-				skipLine := skipText
-				if bytes.Contains(ln, []byte("Disabling lock debugging due to kernel taint")) {
-					skipLine = true
-				} else if textLines > 25 &&
-					bytes.Contains(ln, []byte("Kernel panic - not syncing")) {
-					// If panic_on_warn set, then we frequently have 2 stacks:
-					// one for the actual report (or maybe even more than one),
-					// and then one for panic caused by panic_on_warn. This makes
-					// reports unnecessary long and the panic (current) stack
-					// is always present in the actual report. So we strip the
-					// panic message. However, we check that we have enough lines
-					// before the panic, because sometimes we have, for example,
-					// a single WARNING line without a stack and then the panic
-					// with the stack.
-					skipText = true
-					skipLine = true
-				}
-				if !skipLine {
-					consoleReport = append(consoleReport, ln...)
-					consoleReport = append(consoleReport, '\n')
-					if secondReportPos == 0 {
-						firstReportEnd = len(consoleReport)
-					}
-				}
-			}
+		textLines++
+		skipLine := skipText
+		if bytes.Contains(line, []byte("Disabling lock debugging due to kernel taint")) {
+			skipLine = true
+		} else if textLines > 25 &&
+			bytes.Contains(line, []byte("Kernel panic - not syncing")) {
+			// If panic_on_warn set, then we frequently have 2 stacks:
+			// one for the actual report (or maybe even more than one),
+			// and then one for panic caused by panic_on_warn. This makes
+			// reports unnecessary long and the panic (current) stack
+			// is always present in the actual report. So we strip the
+			// panic message. However, we check that we have enough lines
+			// before the panic, because sometimes we have, for example,
+			// a single WARNING line without a stack and then the panic
+			// with the stack.
+			skipText = true
+			skipLine = true
+		}
+		if !oopsLine && skipLine {
+			continue
+		}
+		report = append(report, stripped...)
+		report = append(report, '\n')
+		if secondReportPos == 0 {
+			reportEnd = len(report)
 		}
-		pos = next + 1
 	}
-	if oops == nil {
-		return
+	return
+}
+
+func (ctx *linux) stripLinePrefix(line []byte, context string) ([]byte, bool) {
+	if last := len(line) - 1; last >= 0 && line[last] == '\r' {
+		line = line[:last]
 	}
-	if secondReportPos == 0 {
-		secondReportPos = len(output)
+	if context == "" {
+		return line, false
 	}
-	logReport = output[startPos:secondReportPos]
-	consoleReportReliable = consoleReport[:firstReportEnd]
-	return
+	questionable := ctx.questionableRe.Match(line) && !bytes.Contains(line, ctx.eoi)
+	start := bytes.Index(line, []byte("] ")) + 2
+	return line[start:], questionable
+}
+
+func (ctx *linux) extractContext(line []byte) string {
+	match := ctx.consoleOutputRe.FindSubmatchIndex(line)
+	if match == nil {
+		return ""
+	}
+	if match[2] == -1 {
+		return "console"
+	}
+	return string(line[match[2]:match[3]])
 }
 
 func (ctx *linux) Symbolize(rep *Report) error {

pkg/report/openbsd.go

@@ -55,7 +55,11 @@ func (ctx *openbsd) ContainsCrash(output []byte) bool {
 }
 
 func (ctx *openbsd) Parse(output []byte) *Report {
-	stripped := bytes.Replace(output, []byte{'\r'}, nil, -1)
+	stripped := bytes.Replace(output, []byte{'\r', '\n'}, []byte{'\n'}, -1)
+	stripped = bytes.Replace(stripped, []byte{'\n', '\r'}, []byte{'\n'}, -1)
+	for len(stripped) != 0 && stripped[0] == '\r' {
+		stripped = stripped[1:]
+	}
 	rep := simpleLineParser(stripped, openbsdOopses, nil, ctx.ignores)
 	if rep == nil {
 		return nil