syz-manager: httpCoverCover panics with nil pointer dereference

[sudipm-mukherjee]

We had been running syzkaller for almost last 6 months without any problem. But since last few weeks we started seeing a syzkaller panic with nil pointer dereference just few hours after starting syzkaller. I have then updated syzkaller to 75b0409 but the same problem still persists.
I have now run syzkaller with -debug and I think this is the relavant part of the log:

16:34:01 executing program 0:
perf_event_open(&(0x7f0000000040)={0x2, 0x80, 0x6f, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, 0x0, @perf_bp={0x0}}, 0x0, 0xffffffffffffffff, 0xffffffffffffffff, 0x0)
r0 = syz_open_dev$tty20(0xc, 0x4, 0x0)
ioctl$TIOCSETD(r0, 0x5423, &(0x7f0000000000)=0x2)
io_setup(0x3e7, &(0x7f0000000580)=<r1=>0x0)
io_submit(r1, 0x1, &(0x7f0000000a40)=[&(0x7f0000000080)={0x4004800, 0x0, 0x0, 0x0, 0x0, r0, 0x0}])

2021/11/11 16:34:01 result hanged=false:
2021/11/11 16:34:01 #0: triaging type=7
2021/11/11 16:34:01 triaging input for call #4 io_submit (new signal=29)
[139256ms] exec opts: procid=0 threaded=1 collide=0 cover=1 comps=0 dedup=1 timeouts=50/5000/1 prog=0 filter=0
spawned worker pid 5952
#0 [139267ms] -> perf_event_open(0x20000040, 0x0, 0xffffffffffffffff, 0xffffffffffffffff, 0x0)
#0 [139267ms] <- perf_event_open=0x3 errno=14 cover=4233
#0 [139268ms] -> syz_open_dev$tty20(0xc, 0x4, 0x14)
#0 [139268ms] <- syz_open_dev$tty20=0x4 errno=14 cover=3911
#0 [139269ms] -> ioctl$TIOCSETD(0x4, 0x5423, 0x20000000)
#0 [139269ms] <- ioctl$TIOCSETD=0x0 errno=14 cover=1453
#0 [139269ms] -> io_setup(0x3e7, 0x20000580)
#0 [139270ms] <- io_setup=0x0 errno=14 cover=17207
[  216.491941] serio: Serial port tty20
#0 [139272ms] -> io_submit(0x7fcd1b6c0000, 0x1, 0x20000a40)
2021/11/11 16:34:02 http: panic serving 172.17.0.1:52052: runtime error: invalid memory address or nil pointer dereference
goroutine 32959 [running]:
net/http.(*conn).serve.func1(0xc00dfb4820)
        /src/goroot/src/net/http/server.go:1772 +0x139
panic(0x10b7fa0, 0x23caa70)
        /src/goroot/src/runtime/panic.go:975 +0x3e3
main.coverToPCs(0x0, 0xc0055aea00, 0xcbe, 0xcbe, 0xc01ead3a98, 0x0, 0x0)
        /src/gopath/src/github.com/google/syzkaller/syz-manager/cover.go:33 +0x9c
main.(*Manager).httpCoverCover(0xc00037ee00, 0x1998800, 0xc000d8a7d0, 0xc006c45100, 0x0, 0x1)
        /src/gopath/src/github.com/google/syzkaller/syz-manager/html.go:298 +0xb10
main.(*Manager).httpCover(...)
        /src/gopath/src/github.com/google/syzkaller/syz-manager/html.go:255
net/http.HandlerFunc.ServeHTTP(0xc000b0f630, 0x1998800, 0xc000d8a7d0, 0xc006c45100)
        /src/goroot/src/net/http/server.go:2012 +0x44
net/http.(*ServeMux).ServeHTTP(0xc000180500, 0x1998800, 0xc000d8a7d0, 0xc006c45100)
        /src/goroot/src/net/http/server.go:2387 +0x1a5
github.com/gorilla/handlers.CompressHandlerLevel.func1(0x1997900, 0xc025a0c1c0, 0xc006c45100)
        /src/gopath/src/github.com/google/syzkaller/vendor/github.com/gorilla/handlers/compress.go:141 +0x671
net/http.HandlerFunc.ServeHTTP(0xc00060e040, 0x1997900, 0xc025a0c1c0, 0xc006c45100)
        /src/goroot/src/net/http/server.go:2012 +0x44
net/http.serverHandler.ServeHTTP(0xc000db61c0, 0x1997900, 0xc025a0c1c0, 0xc006c45100)
        /src/goroot/src/net/http/server.go:2807 +0xa3
net/http.(*conn).serve(0xc00dfb4820, 0x199b700, 0xc006b0db00)
        /src/goroot/src/net/http/server.go:1895 +0x86c
created by net/http.(*Server).Serve
        /src/goroot/src/net/http/server.go:2933 +0x35c

Go version is 1.14.2 and https://dl.google.com/go/go1.14.2.linux-amd64.tar.gz has been used as mentioned in the docs.
Host is a docker image based on Debian Bullseye.
Target is a x86_64 vm image based on Debian Bullseye.

I will be happy to provide any additional debug logs (if needed).

[a-nogikh]

The panic happened when you tried to open the /cover page, right? At least that's what the attached trace, but you did not mention that explicitly.

[sudipm-mukherjee]

@a-nogikh I was not sure yet what was causing this panic or how to reproduce it as the web interface is on a public server and anyone can access it. But after your message I just now tried it and indeed I get the panic immediately if I try to access /cover.

[a-nogikh]

Hmm.. Looked at the code more closely. This is very strange and should not have been happening. I also was not able to reproduce it myself.

Did you try to run a syzkaller instance with a clean workdir (without previous corpus and crashes)? Does it also immediately crash when you try to access /cover? Or does it only happen when you start your instance with some already accumulated corpus?

[sudipm-mukherjee]

@a-nogikh found the problem. This problem started since last few weeks and I was trying to remember what I did around that time. And I started using gcc-11 around that time.
So, now I built the kernel with gcc 10.2.1 and restarted syzkaller, everything worked perfectly, no panic and /cover page works as expected.
Then I moved back to gcc 11.2.0 and built the kernel and tried again and immediately got the panic. Even after removing the old workdir and trying with a new workdir but with gcc 11.2.0 I got the panic.

[a-nogikh]

Good that you have found the triggering factor!

But the very fact that this crash is possible is worrying. Syzkaller is not expected to exhibit such behaviour whatever kernel it runs on VMs. I have compiled the latest Linux kernel with gcc 11.2.0, but it still did not reproduce on my side.

If you don't mind, let's try to dig the problem a bit deeper.

Could you please apply the patch below to syzkaller and make it crash? It would be then very helpful to see your syz-manager configuration and the full log.

diff --git a/syz-manager/cover.go b/syz-manager/cover.go
index 8ddee085f..af97b8d6d 100644
--- a/syz-manager/cover.go
+++ b/syz-manager/cover.go
@@ -22,6 +22,7 @@ var getReportGenerator = func() func(cfg *mgrconfig.Config,
                        log.Logf(0, "initializing coverage information...")
                        rg, err = cover.MakeReportGenerator(cfg.SysTarget, cfg.Type, cfg.KernelObj, cfg.KernelSrc,
                                cfg.KernelBuildSrc, cfg.KernelSubsystem, cfg.ModuleObj, modules)
+                       log.Logf(0, "initialized ReportGenerator: %p %v", rg, err)
                })
                return rg, err
        }
@@ -29,8 +30,11 @@ var getReportGenerator = func() func(cfg *mgrconfig.Config,
 
 func coverToPCs(rg *cover.ReportGenerator, cov []uint32) []uint64 {
        pcs := make([]uint64, 0, len(cov))
-       for _, pc := range cov {
+       for i, pc := range cov {
                pcs = append(pcs, rg.RestorePC(pc))
+               if i == 0 {
+                       log.Logf(0, "RestorePC successfully invoked")
+               }
        }
        return pcs
 }
diff --git a/syz-manager/html.go b/syz-manager/html.go
index dc3e54519..32ec57946 100644
--- a/syz-manager/html.go
+++ b/syz-manager/html.go
@@ -284,6 +284,7 @@ func (mgr *Manager) httpCoverCover(w http.ResponseWriter, r *http.Request, funcF
        }
 
        rg, err := getReportGenerator(mgr.cfg, mgr.modules)
+       log.Logf(0, "getReportGenerator returned %p %v", rg, err)
        if err != nil {
                http.Error(w, fmt.Sprintf("failed to generate coverage profile: %v", err), http.StatusInternalServerError)
                return

[sudipm-mukherjee]

Hi @a-nogikh. First of all, just to be sure that our server setup is not creating the problem, I tried to reproduce the problem in a Debian vm on my laptop and I could reproduce the problem.

The following is with your patch:

2021/11/19 10:37:49 initializing coverage information...
2021/11/19 10:37:49 http: panic serving 10.0.2.2:52084: runtime error: slice bounds out of range [547:480]
goroutine 24 [running]:
net/http.(*conn).serve.func1(0xc0005a2780)
	/home/sudip/syz/goroot/src/net/http/server.go:1772 +0x139
panic(0x11b57c0, 0xc002e8ca20)
	/home/sudip/syz/goroot/src/runtime/panic.go:975 +0x3e3
debug/dwarf.(*Data).Ranges(0xc00011e2c0, 0xc0047e8b70, 0x2, 0x2, 0x3, 0xc008880c60, 0x2)
	/home/sudip/syz/goroot/src/debug/dwarf/entry.go:956 +0x90b
github.com/google/syzkaller/pkg/cover/backend.readTextRanges(0xc00011e2c0, 0xc00f3641b0, 0x0, 0x0, 0x0, 0x60, 0x1237fc0, 0x1, 0xc002d9f9e0, 0xc004341090, ...)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/pkg/cover/backend/dwarf.go:278 +0x262
github.com/google/syzkaller/pkg/cover/backend.elfReadTextRanges(0xc00f3641b0, 0x14afe28, 0xc00000d100, 0xc00f853858, 0xc002d9f9e0, 0xc00f86eae0, 0xc00094ec98, 0xc00029cc00, 0xc00337b320)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/pkg/cover/backend/elf.go:121 +0x2c1
github.com/google/syzkaller/pkg/cover/backend.makeDWARF(0xc00029cc00, 0xc00038aea0, 0x18, 0xc00038aea0, 0x18, 0xc00038aea0, 0x18, 0x0, 0x0, 0x0, ...)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/pkg/cover/backend/dwarf.go:121 +0x345
github.com/google/syzkaller/pkg/cover/backend.makeELF(0xc00029cc00, 0xc00038aea0, 0x18, 0xc00038aea0, 0x18, 0xc00038aea0, 0x18, 0x0, 0x0, 0x0, ...)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/pkg/cover/backend/elf.go:20 +0x121
github.com/google/syzkaller/pkg/cover/backend.Make(0xc00029cc00, 0xc0000e049c, 0x4, 0xc00038aea0, 0x18, 0xc00038aea0, 0x18, 0xc00038aea0, 0x18, 0x0, ...)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/pkg/cover/backend/backend.go:77 +0x134
github.com/google/syzkaller/pkg/cover.MakeReportGenerator(0xc00029cc00, 0xc0000e049c, 0x4, 0xc00038aea0, 0x18, 0xc00038aea0, 0x18, 0xc00038aea0, 0x18, 0x0, ...)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/pkg/cover/report.go:33 +0xf6
main.glob..func1.1.1()
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/syz-manager/cover.go:23 +0x1ae
sync.(*Once).doSlow(0xc0004cae40, 0xc0097fb600)
	/home/sudip/syz/goroot/src/sync/once.go:66 +0xec
sync.(*Once).Do(...)
	/home/sudip/syz/goroot/src/sync/once.go:57
main.glob..func1.1(0xc000600380, 0x0, 0x0, 0x0, 0xc00003e000, 0xc0097fb6d0, 0x4c261b)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/syz-manager/cover.go:21 +0xd8
main.(*Manager).httpCoverCover(0xc000476e00, 0x19998e0, 0xc0000b42d0, 0xc000924000, 0x0, 0x1)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/syz-manager/html.go:286 +0xd5
main.(*Manager).httpCover(...)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/syz-manager/html.go:255
net/http.HandlerFunc.ServeHTTP(0xc00006df20, 0x19998e0, 0xc0000b42d0, 0xc000924000)
	/home/sudip/syz/goroot/src/net/http/server.go:2012 +0x44
net/http.(*ServeMux).ServeHTTP(0xc0004d02c0, 0x19998e0, 0xc0000b42d0, 0xc000924000)
	/home/sudip/syz/goroot/src/net/http/server.go:2387 +0x1a5
github.com/gorilla/handlers.CompressHandlerLevel.func1(0x19989e0, 0xc0107f2380, 0xc000924000)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/vendor/github.com/gorilla/handlers/compress.go:141 +0x671
net/http.HandlerFunc.ServeHTTP(0xc00060e020, 0x19989e0, 0xc0107f2380, 0xc000924000)
	/home/sudip/syz/goroot/src/net/http/server.go:2012 +0x44
net/http.serverHandler.ServeHTTP(0xc000256a80, 0x19989e0, 0xc0107f2380, 0xc000924000)
	/home/sudip/syz/goroot/src/net/http/server.go:2807 +0xa3
net/http.(*conn).serve(0xc0005a2780, 0x199c7e0, 0xc00003c040)
	/home/sudip/syz/goroot/src/net/http/server.go:1895 +0x86c
created by net/http.(*Server).Serve
	/home/sudip/syz/goroot/src/net/http/server.go:2933 +0x35c
2021/11/19 10:37:49 getReportGenerator returned 0x0 <nil>
2021/11/19 10:37:49 http: panic serving 10.0.2.2:52108: runtime error: invalid memory address or nil pointer dereference
goroutine 626 [running]:
net/http.(*conn).serve.func1(0xc00f4b3680)
	/home/sudip/syz/goroot/src/net/http/server.go:1772 +0x139
panic(0x10b8fa0, 0x23cea70)
	/home/sudip/syz/goroot/src/runtime/panic.go:975 +0x3e3
main.coverToPCs(0x0, 0xc001b1c800, 0x583, 0x583, 0x0, 0x2, 0x0)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/syz-manager/cover.go:34 +0xa5
main.(*Manager).httpCoverCover(0xc000476e00, 0x19998e0, 0xc0003a20f0, 0xc003337b00, 0x0, 0x1)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/syz-manager/html.go:309 +0x44c
main.(*Manager).httpCover(...)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/syz-manager/html.go:255
net/http.HandlerFunc.ServeHTTP(0xc00006df20, 0x19998e0, 0xc0003a20f0, 0xc003337b00)
	/home/sudip/syz/goroot/src/net/http/server.go:2012 +0x44
net/http.(*ServeMux).ServeHTTP(0xc0004d02c0, 0x19998e0, 0xc0003a20f0, 0xc003337b00)
	/home/sudip/syz/goroot/src/net/http/server.go:2387 +0x1a5
github.com/gorilla/handlers.CompressHandlerLevel.func1(0x19989e0, 0xc0048a8000, 0xc003337b00)
	/home/sudip/syz/gopath/src/github.com/google/syzkaller/vendor/github.com/gorilla/handlers/compress.go:141 +0x671
net/http.HandlerFunc.ServeHTTP(0xc00060e020, 0x19989e0, 0xc0048a8000, 0xc003337b00)
	/home/sudip/syz/goroot/src/net/http/server.go:2012 +0x44
net/http.serverHandler.ServeHTTP(0xc000256a80, 0x19989e0, 0xc0048a8000, 0xc003337b00)
	/home/sudip/syz/goroot/src/net/http/server.go:2807 +0xa3
net/http.(*conn).serve(0xc00f4b3680, 0x199c7e0, 0xc0033c7580)
	/home/sudip/syz/goroot/src/net/http/server.go:1895 +0x86c
created by net/http.(*Server).Serve
	/home/sudip/syz/goroot/src/net/http/server.go:2933 +0x35c

[a-nogikh]

Thank you for providing the logs!

Now the problem is clear - gcc11 uses DWARF 5, while go 1.14 only supports DWARF 4.

It is only starting from go1.16 (golang/go@05b6118#diff-805cfc619792dc0d7fdc727ac0c075475eff2f326d6d33bccd2cd35f8f6ea655) that the dwarf parsing library should begin to handle that normally. Though it's still weird that it all fails that hard.

Probably syzkaller should detect DWARF version and only proceed if the library it was compiled with permits it...

[sudipm-mukherjee]

Thanks @a-nogikh. So that means there is no immediate fix and I should continue to use gcc-10. But I wonder why I am only seeing this problem. I guess I will try to build syzkaller with latest go and see.

Update: Trying with new go looks like a bit of problem and the existing setup docs will not work. And I dont know much about go to figure out how to do it myself.

[a-nogikh]

But I wonder why I am only seeing this problem.

In the end I was also able to reproduce it - it turned out that earlier I still used the new go version, while it is the combination of old go version + new gcc version that was vital to trigger the problem :)

Trying with new go looks like a bit of problem and the existing setup docs will not work

What went wrong?

You could also try to just check out the repo and execute make inside that directory. It should work fine with newer go distributions.

[sudipm-mukherjee]

Hi @a-nogikh. It has worked. I installed go1.17.3 from Debian and then cloned syzkaller repo and executed make. Everything worked perfectly and the panic is not seen with gcc-11.2.0.
My initial failure was because I tried to do go get -u -d github.com/google/syzkaller/prog as mentioned in the docs, but if I use that command then vendor folder was empty and so make failed.
I will check if there is any plan to backport go1.17.3 to Debian bullseye-backports.

[a-nogikh]

This should no longer be a problem now that we've been using a much newer Go version.

Closing the issue.