From 14dfa4f109c48eccec25e4299f3357c09d7399a7 Mon Sep 17 00:00:00 2001 From: Dmitry Vyukov Date: Tue, 30 Aug 2016 15:19:28 +0200 Subject: report: add a new package for report parsing and processing Move vm.FindCrash to the new package. --- report/report.go | 52 ++++++++++++++++++++++++++ report/report_test.go | 97 ++++++++++++++++++++++++++++++++++++++++++++++++ syz-manager/manager.go | 5 ++- tools/syz-repro/repro.go | 5 ++- vm/vm.go | 49 +----------------------- vm/vm_test.go | 97 ------------------------------------------------ 6 files changed, 156 insertions(+), 149 deletions(-) create mode 100644 report/report.go create mode 100644 report/report_test.go delete mode 100644 vm/vm_test.go diff --git a/report/report.go b/report/report.go new file mode 100644 index 000000000..b56e58bda --- /dev/null +++ b/report/report.go @@ -0,0 +1,52 @@ +// 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 report + +import ( + "bytes" +) + +var oopses = [][]byte{ + []byte("Kernel panic"), + []byte("BUG:"), + []byte("kernel BUG"), + []byte("WARNING:"), + []byte("INFO:"), + []byte("unable to handle"), + []byte("Unable to handle kernel"), + []byte("general protection fault"), + []byte("UBSAN:"), + []byte("unreferenced object"), +} + +// FindCrash searches kernel console output for oops messages. +// Desc contains a more-or-less representative description of the first oops, +// start and end denote region of output with oops message(s). +func FindCrash(output []byte) (desc string, start int, end int, found bool) { + for pos := 0; pos < len(output); { + next := bytes.IndexByte(output[pos:], '\n') + if next != -1 { + next += pos + } else { + next = len(output) + } + for _, oops := range oopses { + match := bytes.Index(output[pos:next], oops) + if match == -1 { + continue + } + if !found { + found = true + start = pos + desc = string(output[pos+match : next]) + if desc[len(desc)-1] == '\r' { + desc = desc[:len(desc)-1] + } + } + end = next + } + pos = next + 1 + } + return +} diff --git a/report/report_test.go b/report/report_test.go new file mode 100644 index 000000000..3b0fd8c22 --- /dev/null +++ b/report/report_test.go @@ -0,0 +1,97 @@ +// Copyright 2015 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 report + +import ( + "strings" + "testing" +) + +func TestFindCrash(t *testing.T) { + tests := map[string]string{ + ` +[ 50.583499] something +[ 50.583499] BUG: unable to handle kernel paging request at 00000000ffffff8a +[ 50.583499] IP: [< inline >] list_del include/linux/list.h:107 +`: "BUG: unable to handle kernel paging request at 00000000ffffff8a", + ` +[ 50.583499] something +[ 50.583499] INFO: rcu_sched self-detected stall on CPU +[ 50.583499] 0: (20822 ticks this GP) idle=94b/140000000000001/0 +`: "INFO: rcu_sched self-detected stall on CPU", + ` +[ 50.583499] general protection fault: 0000 [#1] SMP KASAN +[ 50.583499] Modules linked in: +`: "general protection fault: 0000 [#1] SMP KASAN", + ` +[ 50.583499] BUG: unable to handle kernel NULL pointer dereference at 000000000000003a +[ 50.583499] Modules linked in: +`: "BUG: unable to handle kernel NULL pointer dereference at 000000000000003a", + ` +[ 50.583499] WARNING: CPU: 2 PID: 2636 at ipc/shm.c:162 shm_open+0x74/0x80() +[ 50.583499] Modules linked in: +`: "WARNING: CPU: 2 PID: 2636 at ipc/shm.c:162 shm_open+0x74/0x80()", + ` +[ 50.583499] BUG: KASAN: use after free in remove_wait_queue+0xfb/0x120 at addr ffff88002db3cf50 +[ 50.583499] Write of size 8 by task syzkaller_execu/10568 +`: "BUG: KASAN: use after free in remove_wait_queue+0xfb/0x120 at addr ffff88002db3cf50", + ` +BUG UNIX (Not tainted): kasan: bad access detected +`: "", + ` +[ 50.583499] [ INFO: possible circular locking dependency detected ] +[ 50.583499] 4.3.0+ #30 Not tainted +`: "INFO: possible circular locking dependency detected ]", + ` +BUG: unable to handle kernel paging request at 00000000ffffff8a +IP: [] __call_rcu.constprop.76+0x1f/0x280 kernel/rcu/tree.c:3046 +`: "BUG: unable to handle kernel paging request at 00000000ffffff8a", + ` +================================================================== +BUG: KASAN: slab-out-of-bounds in memcpy+0x1d/0x40 at addr ffff88003a6bd110 +Read of size 8 by task a.out/6260 +`: "BUG: KASAN: slab-out-of-bounds in memcpy+0x1d/0x40 at addr ffff88003a6bd110", + ` +[ 50.583499] unreferenced object 0xffff880039a55260 (size 64): +[ 50.583499] comm "executor", pid 11746, jiffies 4298984475 (age 16.078s) +`: "unreferenced object 0xffff880039a55260 (size 64):", + ` +[ 50.583499] UBSAN: Undefined behaviour in kernel/time/hrtimer.c:310:16 +[ 50.583499] signed integer overflow: +`: "UBSAN: Undefined behaviour in kernel/time/hrtimer.c:310:16", + ` +------------[ cut here ]------------ +kernel BUG at fs/buffer.c:1917! +invalid opcode: 0000 [#1] SMP +`: "kernel BUG at fs/buffer.c:1917!", + ` +BUG: sleeping function called from invalid context at include/linux/wait.h:1095 +in_atomic(): 1, irqs_disabled(): 0, pid: 3658, name: syz-fuzzer +`: "BUG: sleeping function called from invalid context at include/linux/wait.h:1095 ", + ` +------------[ cut here ]------------ +WARNING: CPU: 3 PID: 1975 at fs/locks.c:241 +locks_free_lock_context+0x118/0x180() +`: "WARNING: CPU: 3 PID: 1975 at fs/locks.c:241", + } + for log, crash := range tests { + if strings.Index(log, "\r\n") != -1 { + continue + } + tests[strings.Replace(log, "\n", "\r\n", -1)] = crash + } + for log, crash := range tests { + desc, _, _, found := FindCrash([]byte(log)) + //t.Logf("%v\nexpect '%v', found '%v'\n", log, crash, desc) + if !found && crash != "" { + t.Fatalf("did not find crash message '%v' in:\n%v", crash, log) + } + if found && crash == "" { + t.Fatalf("found bogus crash message '%v' in:\n%v", desc, log) + } + if desc != crash { + t.Fatalf("extracted bad crash message:\n%v\nwant:\n%v", desc, crash) + } + } +} diff --git a/syz-manager/manager.go b/syz-manager/manager.go index fa457a2c8..9f466c963 100644 --- a/syz-manager/manager.go +++ b/syz-manager/manager.go @@ -25,6 +25,7 @@ import ( "github.com/google/syzkaller/config" "github.com/google/syzkaller/cover" "github.com/google/syzkaller/prog" + "github.com/google/syzkaller/report" . "github.com/google/syzkaller/rpctype" "github.com/google/syzkaller/sys" "github.com/google/syzkaller/vm" @@ -351,10 +352,10 @@ func (mgr *Manager) runInstance(vmCfg *vm.Config, first bool) bool { if bytes.Index(output[matchPos:], []byte("executing program")) != -1 { lastExecuteTime = time.Now() } - if _, _, _, found := vm.FindCrash(output[matchPos:]); found { + if _, _, _, found := report.FindCrash(output[matchPos:]); found { // Give it some time to finish writing the error message. waitForOutput(10 * time.Second) - desc, start, end, _ := vm.FindCrash(output[matchPos:]) + desc, start, end, _ := report.FindCrash(output[matchPos:]) start = start + matchPos - beforeContext if start < 0 { start = 0 diff --git a/tools/syz-repro/repro.go b/tools/syz-repro/repro.go index 1e616c986..270533631 100644 --- a/tools/syz-repro/repro.go +++ b/tools/syz-repro/repro.go @@ -19,6 +19,7 @@ import ( "github.com/google/syzkaller/csource" "github.com/google/syzkaller/fileutil" "github.com/google/syzkaller/prog" + "github.com/google/syzkaller/report" "github.com/google/syzkaller/vm" _ "github.com/google/syzkaller/vm/adb" _ "github.com/google/syzkaller/vm/kvm" @@ -64,7 +65,7 @@ func main() { entries := prog.ParseLog(data) log.Printf("parsed %v programs", len(entries)) - crashDesc, crashStart, _, found := vm.FindCrash(data) + crashDesc, crashStart, _, found := report.FindCrash(data) if !found { log.Fatalf("can't find crash message in the log") } @@ -275,7 +276,7 @@ func testImpl(inst vm.Instance, command string, timeout time.Duration) (res bool select { case out := <-outc: output = append(output, out...) - if desc, _, _, found := vm.FindCrash(output); found { + if desc, _, _, found := report.FindCrash(output); found { log.Printf("program crashed with '%s'", desc) return true } diff --git a/vm/vm.go b/vm/vm.go index 1fc52514b..675356928 100644 --- a/vm/vm.go +++ b/vm/vm.go @@ -4,7 +4,6 @@ package vm import ( - "bytes" "errors" "fmt" "io" @@ -76,50 +75,4 @@ func LongPipe() (io.ReadCloser, io.WriteCloser, error) { return r, w, err } -// FindCrash searches kernel console output for oops messages. -// Desc contains a more-or-less representative description of the first oops, -// start and end denote region of output with oops message(s). -func FindCrash(output []byte) (desc string, start int, end int, found bool) { - for pos := 0; pos < len(output); { - next := bytes.IndexByte(output[pos:], '\n') - if next != -1 { - next += pos - } else { - next = len(output) - } - for _, oops := range oopses { - match := bytes.Index(output[pos:next], oops) - if match == -1 { - continue - } - if !found { - found = true - start = pos - desc = string(output[pos+match : next]) - if desc[len(desc)-1] == '\r' { - desc = desc[:len(desc)-1] - } - } - end = next - } - pos = next + 1 - } - return -} - -var ( - oopses = [][]byte{ - []byte("Kernel panic"), - []byte("BUG:"), - []byte("kernel BUG"), - []byte("WARNING:"), - []byte("INFO:"), - []byte("unable to handle"), - []byte("Unable to handle kernel"), - []byte("general protection fault"), - []byte("UBSAN:"), - []byte("unreferenced object"), - } - - TimeoutErr = errors.New("timeout") -) +var TimeoutErr = errors.New("timeout") diff --git a/vm/vm_test.go b/vm/vm_test.go deleted file mode 100644 index d83ad98fa..000000000 --- a/vm/vm_test.go +++ /dev/null @@ -1,97 +0,0 @@ -// Copyright 2015 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 vm - -import ( - "strings" - "testing" -) - -func TestFindCrash(t *testing.T) { - tests := map[string]string{ - ` -[ 50.583499] something -[ 50.583499] BUG: unable to handle kernel paging request at 00000000ffffff8a -[ 50.583499] IP: [< inline >] list_del include/linux/list.h:107 -`: "BUG: unable to handle kernel paging request at 00000000ffffff8a", - ` -[ 50.583499] something -[ 50.583499] INFO: rcu_sched self-detected stall on CPU -[ 50.583499] 0: (20822 ticks this GP) idle=94b/140000000000001/0 -`: "INFO: rcu_sched self-detected stall on CPU", - ` -[ 50.583499] general protection fault: 0000 [#1] SMP KASAN -[ 50.583499] Modules linked in: -`: "general protection fault: 0000 [#1] SMP KASAN", - ` -[ 50.583499] BUG: unable to handle kernel NULL pointer dereference at 000000000000003a -[ 50.583499] Modules linked in: -`: "BUG: unable to handle kernel NULL pointer dereference at 000000000000003a", - ` -[ 50.583499] WARNING: CPU: 2 PID: 2636 at ipc/shm.c:162 shm_open+0x74/0x80() -[ 50.583499] Modules linked in: -`: "WARNING: CPU: 2 PID: 2636 at ipc/shm.c:162 shm_open+0x74/0x80()", - ` -[ 50.583499] BUG: KASAN: use after free in remove_wait_queue+0xfb/0x120 at addr ffff88002db3cf50 -[ 50.583499] Write of size 8 by task syzkaller_execu/10568 -`: "BUG: KASAN: use after free in remove_wait_queue+0xfb/0x120 at addr ffff88002db3cf50", - ` -BUG UNIX (Not tainted): kasan: bad access detected -`: "", - ` -[ 50.583499] [ INFO: possible circular locking dependency detected ] -[ 50.583499] 4.3.0+ #30 Not tainted -`: "INFO: possible circular locking dependency detected ]", - ` -BUG: unable to handle kernel paging request at 00000000ffffff8a -IP: [] __call_rcu.constprop.76+0x1f/0x280 kernel/rcu/tree.c:3046 -`: "BUG: unable to handle kernel paging request at 00000000ffffff8a", - ` -================================================================== -BUG: KASAN: slab-out-of-bounds in memcpy+0x1d/0x40 at addr ffff88003a6bd110 -Read of size 8 by task a.out/6260 -`: "BUG: KASAN: slab-out-of-bounds in memcpy+0x1d/0x40 at addr ffff88003a6bd110", - ` -[ 50.583499] unreferenced object 0xffff880039a55260 (size 64): -[ 50.583499] comm "executor", pid 11746, jiffies 4298984475 (age 16.078s) -`: "unreferenced object 0xffff880039a55260 (size 64):", - ` -[ 50.583499] UBSAN: Undefined behaviour in kernel/time/hrtimer.c:310:16 -[ 50.583499] signed integer overflow: -`: "UBSAN: Undefined behaviour in kernel/time/hrtimer.c:310:16", - ` -------------[ cut here ]------------ -kernel BUG at fs/buffer.c:1917! -invalid opcode: 0000 [#1] SMP -`: "kernel BUG at fs/buffer.c:1917!", - ` -BUG: sleeping function called from invalid context at include/linux/wait.h:1095 -in_atomic(): 1, irqs_disabled(): 0, pid: 3658, name: syz-fuzzer -`: "BUG: sleeping function called from invalid context at include/linux/wait.h:1095 ", - ` -------------[ cut here ]------------ -WARNING: CPU: 3 PID: 1975 at fs/locks.c:241 -locks_free_lock_context+0x118/0x180() -`: "WARNING: CPU: 3 PID: 1975 at fs/locks.c:241", - } - for log, crash := range tests { - if strings.Index(log, "\r\n") != -1 { - continue - } - tests[strings.Replace(log, "\n", "\r\n", -1)] = crash - } - for log, crash := range tests { - desc, _, _, found := FindCrash([]byte(log)) - //t.Logf("%v\nexpect '%v', found '%v'\n", log, crash, desc) - if !found && crash != "" { - t.Fatalf("did not find crash message '%v' in:\n%v", crash, log) - } - if found && crash == "" { - t.Fatalf("found bogus crash message '%v' in:\n%v", desc, log) - } - if desc != crash { - t.Fatalf("extracted bad crash message:\n%v\nwant:\n%v", desc, crash) - } - } -} -- cgit mrf-deployment