8:03 a.m.
make[2]: Entering directory '/home/rjones/d/libnbd/golang'
perl /home/rjones/d/libnbd/podwrapper.pl --section=3 --man libnbd-golang.3 \
--html ../html/libnbd-golang.3.html \
libnbd-golang.pod
/home/rjones/d/libnbd/run go build
write of Go pointer 0x3fa8028000 to non-Go memory 0x3fd2c0fb20
fatal error: Go pointer stored into non-Go memory
runtime stack:
runtime_mstart
../../../libgo/runtime/proc.c:593
goroutine 1 [running, locked to thread]:
Not sure how I should diagnose this one further? I wouldn't normally
worry about RISC-V failures, but they may indicate some kind of arch
generic problem that is just not exposed on x86.
Rich.
--
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-builder quickly builds VMs from scratch
http://libguestfs.org/virt-builder.1.html
8:14 a.m.
On Thu, Jun 09, 2022 at 02:03:04PM +0100, Richard W.M. Jones wrote:
make[2]: Entering directory '/home/rjones/d/libnbd/golang'
perl /home/rjones/d/libnbd/podwrapper.pl --section=3 --man libnbd-golang.3 \
--html ../html/libnbd-golang.3.html \
libnbd-golang.pod
/home/rjones/d/libnbd/run go build
write of Go pointer 0x3fa8028000 to non-Go memory 0x3fd2c0fb20
fatal error: Go pointer stored into non-Go memory
runtime stack:
runtime_mstart
../../../libgo/runtime/proc.c:593
goroutine 1 [running, locked to thread]:
Not sure how I should diagnose this one further? I wouldn't normally
worry about RISC-V failures, but they may indicate some kind of arch
generic problem that is just not exposed on x86.
It could be a bug in the riscv go runtime port, but I think
it is reasonable to consider a latent problem in libnbd code
as these kind of Go/non-Go pointer problems are often
extremely non-deterministic & hard to identify.
Setting GODEBUG=cgocheck=1 or GODEBUG=cgocheck=2 can sometimes
get more info.
If you can get the test to core dump, then plain old GDB core
dump could also be useful - might identify which specific API
is being called, which can help restrict the size of the haystack
for code review.
With regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
9:08 a.m.
On Thu, Jun 09, 2022 at 02:14:07PM +0100, Daniel P. Berrangé wrote:
Setting GODEBUG=cgocheck=1 or GODEBUG=cgocheck=2 can sometimes
get more info.
Took me a while to work out that we are actually setting that already
(in ./run) which explains a couple of things: why I couldn't reproduce
the error using go build directly, and why things like
"GODEBUG=cgocheck=1 ../run go build" make no difference.
If you can get the test to core dump, then plain old GDB core
dump could also be useful - might identify which specific API
is being called, which can help restrict the size of the haystack
for code review.
Eventually careful reading of this page revealed how to do this:
https://pkg.go.dev/runtime
The results unfortunately don't seem very useful. The stack trace
appears to point to where the error was detected rather than where it
was caused, but I've copied it below anyway.
Also attached is the failure in the test suite if you turn *off*
cgocheck, maybe that is useful.
Rich.
$ GODEBUG=cgocheck=2,invalidptr=1 GOTRACEBACK=crash go test -count=1 -v
write of Go pointer 0x3f94026000 to non-Go memory 0x3fbfd6fb20
fatal error: Go pointer stored into non-Go memory
runtime stack:
runtime.dopanic_m
../../../libgo/go/runtime/panic.go:1211
runtime.fatalthrow
../../../libgo/go/runtime/panic.go:1071
runtime.throw
../../../libgo/go/runtime/panic.go:1042
runtime.cgoCheckWriteBarrier..func1
../../../libgo/go/runtime/cgocheck.go:55
runtime.systemstack..func1
../../../libgo/go/runtime/stubs.go:63
runtime_mstart
../../../libgo/runtime/proc.c:593
goroutine 1 [running, locked to thread]:
runtime.mcall
../../../libgo/runtime/proc.c:343
runtime.systemstack
../../../libgo/go/runtime/stubs.go:66
runtime.cgoCheckWriteBarrier
../../../libgo/go/runtime/cgocheck.go:53
runtime.wbBufFlush
../../../libgo/go/runtime/mwbbuf.go:196
runtime.gcWriteBarrier
../../../libgo/go/runtime/mgc_gccgo.go:168
runtime.main
../../../libgo/go/runtime/proc.go:209
Aborted (core dumped)
$ coredumpctl gdb
PID: 191012 (go)
UID: 1001 (rjones)
GID: 1001 (rjones)
Signal: 6 (ABRT)
Timestamp: Thu 2022-06-09 10:04:10 EDT (1min 24s ago)
Command Line: go test -count=1 -v
Executable: /usr/bin/go.gcc
Control Group: /user.slice/user-1001.slice/session-11.scope
Unit: session-11.scope
Slice: user-1001.slice
Session: 11
Owner UID: 1001 (rjones)
Boot ID: c2a10a42ad324704a32e04b47621d3a9
Machine ID: 1640aa86edd8444fb3261e75d4390014
Hostname: nufive.home.annexia.org
Storage:
/var/lib/systemd/coredump/core.go.1001.c2a10a42ad324704a32e04b47621d3a9.191012.1654783450000000.zst
Message: Process 191012 (go) of user 1001 dumped core.
Stack trace of thread 191012:
#0 0x0000003fbe65b084 raise (libc.so.6 + 0x33084)
#1 0x0000003fbf524cca runtime.dieFromSignal (libgo.so.16 + 0xd49cca)
#2 0x0000003fbf542bdc runtime.sigfwdgo (libgo.so.16 + 0xd67bdc)
#3 0x0000003fbfdbb800 n/a (linux-vdso.so.1 + 0x800)
GNU gdb (GDB) Fedora 10.2-4.0.riscv64.fc33
Copyright (C) 2021 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.
Type "show copying" and "show warranty" for details.
This GDB was configured as "riscv64-redhat-linux-gnu".
Type "show configuration" for configuration details.
For bug reporting instructions, please see:
<https://www.gnu.org/software/gdb/bugs/>;.
Find the GDB manual and other documentation resources online at:
<http://www.gnu.org/software/gdb/documentation/>;.
For help, type "help".
Type "apropos word" to search for commands related to "word"...
Reading symbols from /usr/bin/go.gcc...
[New LWP 191012]
[New LWP 191028]
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib64/lp64d/libthread_db.so.1".
Core was generated by `go test -count=1 -v'.
Program terminated with signal SIGABRT, Aborted.
#0 0x0000003fbe65b084 in raise () from /lib64/lp64d/libc.so.6
Missing separate debuginfos, use: dnf debuginfo-install gcc-go-10.3.1-1.fc33.riscv64
--Type <RET> for more, q to quit, c to continue without paging--
[Current thread is 1 (Thread 0x3fbe5f5630 (LWP 191012))]
(gdb) t a a bt
Thread 2 (Thread 0x3f99563150 (LWP 191028)):
#0 0x0000003fbe6cda60 in syscall () from /lib64/lp64d/libc.so.6
#1 0x0000003fbf246f88 in __go_syscall6 (flag=<optimized out>, a1=<optimized
out>, a2=<optimized out>, a3=<optimized out>, a4=<optimized out>,
a5=<optimized out>, a6=<optimized out>) at
../../../libgo/runtime/go-varargs.c:109
#2 0x0000003fbf51f05c in runtime.futex (val3=<optimized out>, addr2=<optimized
out>, ts=<optimized out>, val=<optimized out>, op=<optimized out>,
addr=<optimized out>) at ../../../libgo/go/runtime/os_linux.go:17
#3 runtime.futexsleep (addr=0x3fbfd6e878 <runtime.sched+240>, val=<optimized
out>, ns=<optimized out>) at ../../../libgo/go/runtime/os_linux.go:59
#4 0x0000003fbf52d70c in runtime.notetsleep_internal (n=n@entry=0x3fbfd6e878
<runtime.sched+240>, ns=ns@entry=60000000000) at
../../../libgo/go/runtime/lock_futex.go:204
#5 0x0000003fbf52d8ce in runtime.notetsleep (n=n@entry=0x3fbfd6e878
<runtime.sched+240>, ns=60000000000) at ../../../libgo/go/runtime/lock_futex.go:227
#6 0x0000003fbf54de9c in runtime.sysmon () at ../../../libgo/go/runtime/proc.go:4210
#7 0x0000003fbf5501a6 in runtime.mstart1 () at ../../../libgo/go/runtime/proc.go:1074
#8 0x0000003fbf24779e in runtime_mstart (arg=<optimized out>) at
../../../libgo/runtime/proc.c:611
#9 0x0000003fbe613606 in start_thread () from /lib64/lp64d/libpthread.so.0
#10 0x0000003fbe6d028e in __thread_start () from /lib64/lp64d/libc.so.6
Thread 1 (Thread 0x3fbe5f5630 (LWP 191012)):
#0 0x0000003fbe65b084 in raise () from /lib64/lp64d/libc.so.6
#1 0x0000003fbf524cca in runtime.dieFromSignal (sig=sig@entry=6) at
../../../libgo/go/runtime/signal_unix.go:668
#2 0x0000003fbf542bdc in runtime.sigfwdgo (ctx=0x3f99973c40, info=0x3f99973bc0,
sig=<optimized out>) at ../../../libgo/go/runtime/signal_unix.go:883
#3 runtime.sigtrampgo (sig=<optimized out>, info=0x3f99973bc0, ctx=0x3f99973c40) at
../../../libgo/go/runtime/signal_unix.go:392
#4 <signal handler called>
#5 0x0000003fbe65b084 in raise () from /lib64/lp64d/libc.so.6
#6 0x0000003fbf524cca in runtime.dieFromSignal (sig=sig@entry=6) at
../../../libgo/go/runtime/signal_unix.go:668
#7 0x0000003fbf524d42 in runtime.crash () at
../../../libgo/go/runtime/signal_unix.go:763
#8 0x0000003fbf529132 in runtime.fatalthrow () at
../../../libgo/go/runtime/panic.go:1072
#9 runtime.throw (s=...) at ../../../libgo/go/runtime/panic.go:1042
#10 0x0000003fbf5291c4 in runtime.cgoCheckWriteBarrier..func1 () at
../../../libgo/go/runtime/cgocheck.go:55
#11 0x0000003fbf51ff3e in runtime.systemstack..func1 (origg=0x3f94000a80) at
../../../libgo/go/runtime/stubs.go:63
#12 0x0000003fbf24776e in runtime_mstart (arg=<optimized out>) at
../../../libgo/runtime/proc.c:593
#13 0x0000000000035abe in main (argc=<optimized out>, argv=<optimized out>) at
../../../libgo/runtime/go-main.c:58
#14 0x0000003fbe64b956 in __libc_start_main () from /lib64/lp64d/libc.so.6
#15 0x0000000000035afc in _start ()
--
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
nbdkit - Flexible, fast NBD server with plugins
https://gitlab.com/nbdkit/nbdkit
9:20 a.m.
On Thu, Jun 09, 2022 at 03:08:51PM +0100, Richard W.M. Jones wrote:
On Thu, Jun 09, 2022 at 02:14:07PM +0100, Daniel P. Berrangé wrote:
> If you can get the test to core dump, then plain old GDB core
> dump could also be useful - might identify which specific API
> is being called, which can help restrict the size of the haystack
> for code review.
Eventually careful reading of this page revealed how to do this:
https://pkg.go.dev/runtime
The results unfortunately don't seem very useful. The stack trace
appears to point to where the error was detected rather than where it
was caused, but I've copied it below anyway.
Also attached is the failure in the test suite if you turn *off*
cgocheck, maybe that is useful.
--
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
nbdkit - Flexible, fast NBD server with plugins
https://gitlab.com/nbdkit/nbdkit
+ requires nbdkit --version
+ go test -count=1 -v
=== RUN Test010Load
--- PASS: Test010Load (0.00s)
=== RUN TestAioBuffer
--- PASS: TestAioBuffer (0.00s)
=== RUN TestAioBufferFree
--- PASS: TestAioBufferFree (0.00s)
=== RUN TestAioBufferBytesAfterFree
SIGABRT: abort
PC=0x3fdf6f9bac m=0 sigcode=18446744073709551610
So suggesting TestAioBufferBytesAfterFree is as fault, but quite
odd as that test case is trivial and whle it allocates some
native memory it doesn't seem to write to it. Unless the problem
happened in an earlier test case and we have delayed detection ?
I guess I'd try throwing darts at the wall by chopping out bits
of test code to see what makes it disappear.
Perhaps also try swapping MakeAioBuffer with MakeAioBufferZero
in case pre-existing data into the C.malloc()d block is confusing
Go ?
With regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
10:24 a.m.
On Thu, Jun 09, 2022 at 03:20:02PM +0100, Daniel P. Berrangé wrote:
> + go test -count=1 -v
> === RUN Test010Load
> --- PASS: Test010Load (0.00s)
> === RUN TestAioBuffer
> --- PASS: TestAioBuffer (0.00s)
> === RUN TestAioBufferFree
> --- PASS: TestAioBufferFree (0.00s)
> === RUN TestAioBufferBytesAfterFree
> SIGABRT: abort
> PC=0x3fdf6f9bac m=0 sigcode=18446744073709551610
So suggesting TestAioBufferBytesAfterFree is as fault, but quite
odd as that test case is trivial and whle it allocates some
native memory it doesn't seem to write to it. Unless the problem
happened in an earlier test case and we have delayed detection ?
I guess I'd try throwing darts at the wall by chopping out bits
of test code to see what makes it disappear.
Perhaps also try swapping MakeAioBuffer with MakeAioBufferZero
in case pre-existing data into the C.malloc()d block is confusing
Go ?
Interestingly if I remove libnbd_020_aio_buffer_test.go completely,
and disable GODEBUG, then the tests pass. (Reproducer commands at end
of email). So I guess at least one of the problems is confined to
this test and/or functions it calls in the main library.
Unfortunately this test is huge.
At your suggestion, replacing every MakeAioBuffer with
MakeAioBufferZero in that test, but it didn't help. Also tried
replacing malloc -> calloc in the aio_buffer.go implementation which
didn't help.
I'll try some more random things ...
Rich.
$ emacs -nw run.in # comment out GODEBUG line
$ emacs -nw golang/Makefile.am # remove libnbd_020_aio_buffer_test.go line
$ mv golang/libnbd_020_aio_buffer_test.go golang/libnbd_020_aio_buffer_test.nogo
$ make run
$ make
$ make -C golang check
...
PASS: run-tests.sh
...
--
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
Fedora Windows cross-compiler. Compile Windows programs, test, and
build Windows installers. Over 100 libraries supported.
http://fedoraproject.org/wiki/MinGW
10:48 a.m.
On Thu, Jun 09, 2022 at 04:24:12PM +0100, Richard W.M. Jones wrote:
On Thu, Jun 09, 2022 at 03:20:02PM +0100, Daniel P. Berrangé wrote:
> > + go test -count=1 -v
> > === RUN Test010Load
> > --- PASS: Test010Load (0.00s)
> > === RUN TestAioBuffer
> > --- PASS: TestAioBuffer (0.00s)
> > === RUN TestAioBufferFree
> > --- PASS: TestAioBufferFree (0.00s)
> > === RUN TestAioBufferBytesAfterFree
> > SIGABRT: abort
> > PC=0x3fdf6f9bac m=0 sigcode=18446744073709551610
>
> So suggesting TestAioBufferBytesAfterFree is as fault, but quite
> odd as that test case is trivial and whle it allocates some
> native memory it doesn't seem to write to it. Unless the problem
> happened in an earlier test case and we have delayed detection ?
>
> I guess I'd try throwing darts at the wall by chopping out bits
> of test code to see what makes it disappear.
>
> Perhaps also try swapping MakeAioBuffer with MakeAioBufferZero
> in case pre-existing data into the C.malloc()d block is confusing
> Go ?
Interestingly if I remove libnbd_020_aio_buffer_test.go completely,
and disable GODEBUG, then the tests pass. (Reproducer commands at end
of email). So I guess at least one of the problems is confined to
this test and/or functions it calls in the main library.
Unfortunately this test is huge.
At your suggestion, replacing every MakeAioBuffer with
MakeAioBufferZero in that test, but it didn't help. Also tried
replacing malloc -> calloc in the aio_buffer.go implementation which
didn't help.
I'll try some more random things ...
Adding a few printf's shows something interesting:
=== RUN TestAioBufferBytesAfterFree
calling Free on 0x3fbc1882b0
calling C.GoBytes on 0x3fbc1882b0
SIGABRT: abort
PC=0x3fe6aaebac m=0 sigcode=18446744073709551610
goroutine 21 [running]:
gsignal
:0
abort
:0
runtime.throwException
../../../libgo/runtime/go-unwind.c:128
runtime.unwindStack
../../../libgo/go/runtime/panic.go:535
panic
../../../libgo/go/runtime/panic.go:750
runtime.panicmem
../../../libgo/go/runtime/panic.go:210
runtime.sigpanic
../../../libgo/go/runtime/signal_unix.go:634
_wordcopy_fwd_aligned
:0
__GI_memmove
:0
runtime.stringtoslicebyte
../../../libgo/go/runtime/string.go:155
__go_string_to_byte_array
../../../libgo/go/runtime/string.go:509
_cgo_23192bdcbd72_Cfunc_GoBytes
./cgo-c-prolog-gccgo:46
This is a simple use after free because the Free function in
aio_buffer.go frees the array and then the Bytes function attempts to
copy b.Size bytes from the NULL pointer.
I didn't write this test so I'm not quite sure what it's trying to
achieve. It seems to be deliberately trying to cause a panic, but
causes a segfault instead? (And why only on RISC-V?)
func TestAioBufferBytesAfterFree(t *testing.T) {
buf := MakeAioBuffer(uint(32))
buf.Free()
defer func() {
if r := recover(); r == nil {
t.Fatal("Did not recover from panic calling Bytes() after
Free()")
}
}()
buf.Bytes()
}
Since this only happens on RISC-V I guess it might be something to do
with the golang implementation on this architecture being unable to
turn segfaults into panics.
Removing all three *AfterFree tests fixes the tests.
It seems a bit of an odd function however. Wouldn't it be better to
changes the Bytes function so that it tests if the pointer is NULL and
panics?
NB: this _does not_ address the other problem where GODEBUG=cgocheck=2
complains about "fatal error: Go pointer stored into non-Go memory".
Rich.
--
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
libguestfs lets you edit virtual machines. Supports shell scripting,
bindings from many languages. http://libguestfs.org
11 a.m.
On Thu, Jun 09, 2022 at 04:48:34PM +0100, Richard W.M. Jones wrote:
On Thu, Jun 09, 2022 at 04:24:12PM +0100, Richard W.M. Jones wrote:
> On Thu, Jun 09, 2022 at 03:20:02PM +0100, Daniel P. Berrangé wrote:
> > > + go test -count=1 -v
> > > === RUN Test010Load
> > > --- PASS: Test010Load (0.00s)
> > > === RUN TestAioBuffer
> > > --- PASS: TestAioBuffer (0.00s)
> > > === RUN TestAioBufferFree
> > > --- PASS: TestAioBufferFree (0.00s)
> > > === RUN TestAioBufferBytesAfterFree
> > > SIGABRT: abort
> > > PC=0x3fdf6f9bac m=0 sigcode=18446744073709551610
> >
> > So suggesting TestAioBufferBytesAfterFree is as fault, but quite
> > odd as that test case is trivial and whle it allocates some
> > native memory it doesn't seem to write to it. Unless the problem
> > happened in an earlier test case and we have delayed detection ?
> >
> > I guess I'd try throwing darts at the wall by chopping out bits
> > of test code to see what makes it disappear.
> >
> > Perhaps also try swapping MakeAioBuffer with MakeAioBufferZero
> > in case pre-existing data into the C.malloc()d block is confusing
> > Go ?
>
> Interestingly if I remove libnbd_020_aio_buffer_test.go completely,
> and disable GODEBUG, then the tests pass. (Reproducer commands at end
> of email). So I guess at least one of the problems is confined to
> this test and/or functions it calls in the main library.
> Unfortunately this test is huge.
>
> At your suggestion, replacing every MakeAioBuffer with
> MakeAioBufferZero in that test, but it didn't help. Also tried
> replacing malloc -> calloc in the aio_buffer.go implementation which
> didn't help.
>
> I'll try some more random things ...
Adding a few printf's shows something interesting:
=== RUN TestAioBufferBytesAfterFree
calling Free on 0x3fbc1882b0
calling C.GoBytes on 0x3fbc1882b0
SIGABRT: abort
PC=0x3fe6aaebac m=0 sigcode=18446744073709551610
goroutine 21 [running]:
gsignal
:0
abort
:0
runtime.throwException
../../../libgo/runtime/go-unwind.c:128
runtime.unwindStack
../../../libgo/go/runtime/panic.go:535
panic
../../../libgo/go/runtime/panic.go:750
runtime.panicmem
../../../libgo/go/runtime/panic.go:210
runtime.sigpanic
../../../libgo/go/runtime/signal_unix.go:634
_wordcopy_fwd_aligned
:0
__GI_memmove
:0
runtime.stringtoslicebyte
../../../libgo/go/runtime/string.go:155
__go_string_to_byte_array
../../../libgo/go/runtime/string.go:509
_cgo_23192bdcbd72_Cfunc_GoBytes
./cgo-c-prolog-gccgo:46
This is a simple use after free because the Free function in
aio_buffer.go frees the array and then the Bytes function attempts to
copy b.Size bytes from the NULL pointer.
Well it isn't use-after-free, because we've cleared the
pointer we freed.
Rather we're simply trying to reference the NULL pointer,
I didn't write this test so I'm not quite sure what it's
trying to
achieve. It seems to be deliberately trying to cause a panic, but
causes a segfault instead? (And why only on RISC-V?)
IIUC, the kernel will map a page without read/write perms
at address 0x0 in userspace. Thus a NULL pointer reference
causes a SEGV to userspace. Golang tries to catch this
SEGV and turn it into a panic I assume.
Assuming the kernel isn't doing something wierd on Risc-V
with the userspace mapping at 0x0, then points to the
Golang SEGV handler on RISCV.
func TestAioBufferBytesAfterFree(t *testing.T) {
buf := MakeAioBuffer(uint(32))
buf.Free()
defer func() {
if r := recover(); r == nil {
t.Fatal("Did not recover from panic calling Bytes() after
Free()")
}
}()
buf.Bytes()
}
Since this only happens on RISC-V I guess it might be something to do
with the golang implementation on this architecture being unable to
turn segfaults into panics.
Removing all three *AfterFree tests fixes the tests.
It seems a bit of an odd function however. Wouldn't it be better to
changes the Bytes function so that it tests if the pointer is NULL and
panics?
In theory I guess both should be equivalent in terms of
semantics for the caller.
Also I feel like 'Free' ought to set 'b.Size = 0' after
it set 'b.P = nul'. That should solve the problem for
the Bytes & Slice method tests at least, but probably not
the Get method test.
NB: this _does not_ address the other problem where
GODEBUG=cgocheck=2
complains about "fatal error: Go pointer stored into non-Go memory".
Maybe that message across comes from the Go signal handler that's
trying to cope with the SEGV from the NULL reference, causing it
to trip over itself & thus not turn the problem into a pnaic.
With regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
11:22 a.m.
On Thu, Jun 9, 2022 at 6:48 PM Richard W.M. Jones <rjones(a)redhat.com> wrote:
On Thu, Jun 09, 2022 at 04:24:12PM +0100, Richard W.M. Jones wrote:
> On Thu, Jun 09, 2022 at 03:20:02PM +0100, Daniel P. Berrangé wrote:
> > > + go test -count=1 -v
> > > === RUN Test010Load
> > > --- PASS: Test010Load (0.00s)
> > > === RUN TestAioBuffer
> > > --- PASS: TestAioBuffer (0.00s)
> > > === RUN TestAioBufferFree
> > > --- PASS: TestAioBufferFree (0.00s)
> > > === RUN TestAioBufferBytesAfterFree
> > > SIGABRT: abort
> > > PC=0x3fdf6f9bac m=0 sigcode=18446744073709551610
> >
> > So suggesting TestAioBufferBytesAfterFree is as fault, but quite
> > odd as that test case is trivial and whle it allocates some
> > native memory it doesn't seem to write to it. Unless the problem
> > happened in an earlier test case and we have delayed detection ?
> >
> > I guess I'd try throwing darts at the wall by chopping out bits
> > of test code to see what makes it disappear.
> >
> > Perhaps also try swapping MakeAioBuffer with MakeAioBufferZero
> > in case pre-existing data into the C.malloc()d block is confusing
> > Go ?
>
> Interestingly if I remove libnbd_020_aio_buffer_test.go completely,
> and disable GODEBUG, then the tests pass. (Reproducer commands at end
> of email). So I guess at least one of the problems is confined to
> this test and/or functions it calls in the main library.
> Unfortunately this test is huge.
>
> At your suggestion, replacing every MakeAioBuffer with
> MakeAioBufferZero in that test, but it didn't help. Also tried
> replacing malloc -> calloc in the aio_buffer.go implementation which
> didn't help.
>
> I'll try some more random things ...
Adding a few printf's shows something interesting:
=== RUN TestAioBufferBytesAfterFree
calling Free on 0x3fbc1882b0
calling C.GoBytes on 0x3fbc1882b0
SIGABRT: abort
PC=0x3fe6aaebac m=0 sigcode=18446744073709551610
goroutine 21 [running]:
gsignal
:0
abort
:0
runtime.throwException
../../../libgo/runtime/go-unwind.c:128
runtime.unwindStack
../../../libgo/go/runtime/panic.go:535
panic
../../../libgo/go/runtime/panic.go:750
runtime.panicmem
../../../libgo/go/runtime/panic.go:210
runtime.sigpanic
../../../libgo/go/runtime/signal_unix.go:634
_wordcopy_fwd_aligned
:0
__GI_memmove
:0
runtime.stringtoslicebyte
../../../libgo/go/runtime/string.go:155
__go_string_to_byte_array
../../../libgo/go/runtime/string.go:509
_cgo_23192bdcbd72_Cfunc_GoBytes
./cgo-c-prolog-gccgo:46
This is a simple use after free because the Free function in
aio_buffer.go frees the array and then the Bytes function attempts to
copy b.Size bytes from the NULL pointer.
I didn't write this test so I'm not quite sure what it's trying to
achieve.
The test verifies that using the buffer in the wrong way fails in a clean
way (panic) and not silent double free like it was before
https://gitlab.com/nbdkit/libnbd/-/commit/3394f47556cac009fa7d39c9e2f7e5f...
It seems to be deliberately trying to cause a panic, but
causes a segfault instead? (And why only on RISC-V?)
func TestAioBufferBytesAfterFree(t *testing.T) {
buf := MakeAioBuffer(uint(32))
buf.Free()
defer func() {
if r := recover(); r == nil {
t.Fatal("Did not recover from panic calling Bytes() after
Free()")
}
}()
buf.Bytes()
}
Since this only happens on RISC-V I guess it might be something to do
with the golang implementation on this architecture being unable to
turn segfaults into panics.
Removing all three *AfterFree tests fixes the tests.
But this hides the real issue - if users use Bytes() in the wrong way, we want
the panic, not the segfault - the tests are good!
It seems a bit of an odd function however. Wouldn't it be better
to
changes the Bytes function so that it tests if the pointer is NULL and
panics?
I cannot find now any docs for GoBytes, maybe I tested that it panics
in this case,
but this does not work this arch (bug?). Panic with a good error message about
the wrong usage will be much better.
NB: this _does not_ address the other problem where GODEBUG=cgocheck=2
complains about "fatal error: Go pointer stored into non-Go memory".
Do we keep go pointers in buffers allocated in C?
Nir
11:31 a.m.
On Thu, Jun 09, 2022 at 05:00:46PM +0100, Daniel P. Berrangé wrote:
Well it isn't use-after-free, because we've cleared the
pointer we freed.
Yes, indeed that's what I meant to say!
> It seems a bit of an odd function however. Wouldn't it be
better to
> changes the Bytes function so that it tests if the pointer is NULL and
> panics?
In theory I guess both should be equivalent in terms of
semantics for the caller.
Also I feel like 'Free' ought to set 'b.Size = 0' after
it set 'b.P = nul'. That should solve the problem for
the Bytes & Slice method tests at least, but probably not
the Get method test.
Making this change has very unexpected effects (although I think I
partially understand what's going on). Note this is replicable on
x86-64.
=== RUN TestAioBufferBytesAfterFree
libnbd_020_aio_buffer_test.go:108: Did not recover from panic calling Bytes() after
Free()
--- FAIL: TestAioBufferBytesAfterFree (0.00s)
This is failing because C.GoBytes does _not_ segfault, since it is
being asked to memcpy a zero length buffer.
=== RUN TestAioBufferSliceAfterFree
--- PASS: TestAioBufferSliceAfterFree (0.00s)
I think I understand why this test now passes, because of the way that
slices are created using b.Size which is now 0.
=== RUN TestAioBufferGetAfterFree
--- PASS: TestAioBufferGetAfterFree (0.00s)
Why does this test now pass?! It's still dereferencing a NULL
pointer.
I wonder why Get doesn't do bounds checking? That seems like a
general bug.
> NB: this _does not_ address the other problem where
GODEBUG=cgocheck=2
> complains about "fatal error: Go pointer stored into non-Go memory".
Maybe that message across comes from the Go signal handler that's
trying to cope with the SEGV from the NULL reference, causing it
to trip over itself & thus not turn the problem into a pnaic.
We're rebuilding the latest Fedora packages, so my plan here is to try
with the newest golang when it becomes available and hope it's been
fixed upstream (if it's a golang problem).
Rich.
--
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
Fedora Windows cross-compiler. Compile Windows programs, test, and
build Windows installers. Over 100 libraries supported.
http://fedoraproject.org/wiki/MinGW
11:33 a.m.
On Thu, Jun 09, 2022 at 07:22:45PM +0300, Nir Soffer wrote:
On Thu, Jun 9, 2022 at 6:48 PM Richard W.M. Jones
<rjones(a)redhat.com> wrote:
> NB: this _does not_ address the other problem where GODEBUG=cgocheck=2
> complains about "fatal error: Go pointer stored into non-Go memory".
Do we keep go pointers in buffers allocated in C?
I guess we must do, but I'm not sure where.
However it's possible that golang on RISC-V is buggy, particularly the
somewhat old version that we are still using.
Rich.
--
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
virt-top is 'top' for virtual machines. Tiny program with many
powerful monitoring features, net stats, disk stats, logging, etc.
http://people.redhat.com/~rjones/virt-top
1:23 p.m.
On Thu, Jun 9, 2022 at 6:24 PM Richard W.M. Jones <rjones(a)redhat.com> wrote:
On Thu, Jun 09, 2022 at 03:20:02PM +0100, Daniel P. Berrangé wrote:
> > + go test -count=1 -v
> > === RUN Test010Load
> > --- PASS: Test010Load (0.00s)
> > === RUN TestAioBuffer
> > --- PASS: TestAioBuffer (0.00s)
> > === RUN TestAioBufferFree
> > --- PASS: TestAioBufferFree (0.00s)
> > === RUN TestAioBufferBytesAfterFree
> > SIGABRT: abort
> > PC=0x3fdf6f9bac m=0 sigcode=18446744073709551610
>
> So suggesting TestAioBufferBytesAfterFree is as fault, but quite
> odd as that test case is trivial and whle it allocates some
> native memory it doesn't seem to write to it. Unless the problem
> happened in an earlier test case and we have delayed detection ?
>
> I guess I'd try throwing darts at the wall by chopping out bits
> of test code to see what makes it disappear.
>
> Perhaps also try swapping MakeAioBuffer with MakeAioBufferZero
> in case pre-existing data into the C.malloc()d block is confusing
> Go ?
Interestingly if I remove libnbd_020_aio_buffer_test.go completely,
and disable GODEBUG, then the tests pass. (Reproducer commands at end
of email). So I guess at least one of the problems is confined to
this test and/or functions it calls in the main library.
Unfortunately this test is huge.
At your suggestion, replacing every MakeAioBuffer with
MakeAioBufferZero in that test, but it didn't help. Also tried
replacing malloc -> calloc in the aio_buffer.go implementation which
didn't help.
I'll try some more random things ...
Rich.
$ emacs -nw run.in # comment out GODEBUG line
$ emacs -nw golang/Makefile.am # remove libnbd_020_aio_buffer_test.go line
$ mv golang/libnbd_020_aio_buffer_test.go golang/libnbd_020_aio_buffer_test.nogo
$ make run
$ make
$ make -C golang check
...
PASS: run-tests.sh
So when skipping libnbd_020_aio_buffer_test.go we don't get the warning about
Go pointer in C memory?
If true, can you find the test triggering this issue?
You can run only some tests using -run={regex}, for example:
$ go test -v -run=TestAioBuffer.+AfterFree
=== RUN TestAioBufferBytesAfterFree
--- PASS: TestAioBufferBytesAfterFree (0.00s)
=== RUN TestAioBufferSliceAfterFree
--- PASS: TestAioBufferSliceAfterFree (0.00s)
=== RUN TestAioBufferGetAfterFree
--- PASS: TestAioBufferGetAfterFree (0.00s)
PASS
1:30 p.m.
On Thu, Jun 09, 2022 at 05:33:03PM +0100, Richard W.M. Jones wrote:
On Thu, Jun 09, 2022 at 07:22:45PM +0300, Nir Soffer wrote:
> On Thu, Jun 9, 2022 at 6:48 PM Richard W.M. Jones <rjones(a)redhat.com> wrote:
> > NB: this _does not_ address the other problem where GODEBUG=cgocheck=2
> > complains about "fatal error: Go pointer stored into non-Go memory".
>
> Do we keep go pointers in buffers allocated in C?
I guess we must do, but I'm not sure where.
However it's possible that golang on RISC-V is buggy, particularly the
somewhat old version that we are still using.
Yeah, my money is on this being a bug in the go runtime, the signal
stuff in particular is a bit hairy in the go impl that I looked at.
With regards,
Daniel
--
|: https://berrange.com -o- https://www.flickr.com/photos/dberrange :|
|: https://libvirt.org -o- https://fstop138.berrange.com :|
|: https://entangle-photo.org -o- https://www.instagram.com/dberrange :|
1:50 p.m.
On Thu, Jun 09, 2022 at 09:23:50PM +0300, Nir Soffer wrote:
On Thu, Jun 9, 2022 at 6:24 PM Richard W.M. Jones
<rjones(a)redhat.com> wrote:
> $ emacs -nw run.in # comment out GODEBUG line
...
> $ make -C golang check
> ...
> PASS: run-tests.sh
So when skipping libnbd_020_aio_buffer_test.go we don't get the warning about
Go pointer in C memory?
No, I commented out the GODEBUG line.
Enabling the GODEBUG line (ie. the normal case) gives:
$ uname -m
riscv64
$ git restore run.in
$ make
...
/home/rjones/d/libnbd/run go build
write of Go pointer 0x3fbc028000 to non-Go memory 0x3fe899bb20
fatal error: Go pointer stored into non-Go memory
runtime stack:
runtime.dopanic_m
../../../libgo/go/runtime/panic.go:1211
runtime.fatalthrow
../../../libgo/go/runtime/panic.go:1071
runtime.throw
../../../libgo/go/runtime/panic.go:1042
runtime.cgoCheckWriteBarrier..func1
../../../libgo/go/runtime/cgocheck.go:55
runtime.systemstack..func1
../../../libgo/go/runtime/stubs.go:63
runtime_mstart
../../../libgo/runtime/proc.c:593
goroutine 1 [running, locked to thread]:
runtime.mcall
../../../libgo/runtime/proc.c:343
runtime.systemstack
../../../libgo/go/runtime/stubs.go:66
runtime.cgoCheckWriteBarrier
../../../libgo/go/runtime/cgocheck.go:53
runtime.wbBufFlush
../../../libgo/go/runtime/mwbbuf.go:196
runtime.gcWriteBarrier
../../../libgo/go/runtime/mgc_gccgo.go:168
runtime.main
../../../libgo/go/runtime/proc.go:209
make[2]: *** [Makefile:1089: all-local] Aborted (core dumped)
The stack trace is not very interesting:
Thread 2 (Thread 0x3fbbfff150 (LWP 269087)):
#0 0x0000003fe72f9a60 in syscall () from /lib64/lp64d/libc.so.6
#1 0x0000003fe7e72f88 in __go_syscall6 (flag=<optimized out>, a1=<optimized
out>, a2=<optimized out>, a3=<optimized out>, a4=<optimized out>,
a5=<optimized out>, a6=<optimized out>) at
../../../libgo/runtime/go-varargs.c:109
#2 0x0000003fe814b05c in runtime.futex (val3=<optimized out>, addr2=<optimized
out>, ts=<optimized out>, val=<optimized out>, op=<optimized out>,
addr=<optimized out>) at ../../../libgo/go/runtime/os_linux.go:17
#3 runtime.futexsleep (addr=0x3fe899a878 <runtime.sched+240>, val=<optimized
out>, ns=<optimized out>) at ../../../libgo/go/runtime/os_linux.go:59
#4 0x0000003fe815970c in runtime.notetsleep_internal (n=n@entry=0x3fe899a878
<runtime.sched+240>, ns=ns@entry=60000000000) at
../../../libgo/go/runtime/lock_futex.go:204
#5 0x0000003fe81598ce in runtime.notetsleep (n=n@entry=0x3fe899a878
<runtime.sched+240>, ns=60000000000) at ../../../libgo/go/runtime/lock_futex.go:227
#6 0x0000003fe8179e9c in runtime.sysmon () at ../../../libgo/go/runtime/proc.go:4210
#7 0x0000003fe817c1a6 in runtime.mstart1 () at ../../../libgo/go/runtime/proc.go:1074
#8 0x0000003fe7e7379e in runtime_mstart (arg=<optimized out>) at
../../../libgo/runtime/proc.c:611
#9 0x0000003fe723f606 in start_thread () from /lib64/lp64d/libpthread.so.0
#10 0x0000003fe72fc28e in __thread_start () from /lib64/lp64d/libc.so.6
Thread 1 (Thread 0x3fe7221630 (LWP 269040)):
#0 0x0000003fe7287084 in raise () from /lib64/lp64d/libc.so.6
#1 0x0000003fe8150cca in runtime.dieFromSignal (sig=sig@entry=6) at
../../../libgo/go/runtime/signal_unix.go:668
#2 0x0000003fe816ebdc in runtime.sigfwdgo (ctx=0x3fc059fc40, info=0x3fc059fbc0,
sig=<optimized out>) at ../../../libgo/go/runtime/signal_unix.go:883
#3 runtime.sigtrampgo (sig=<optimized out>, info=0x3fc059fbc0, ctx=0x3fc059fc40) at
../../../libgo/go/runtime/signal_unix.go:392
#4 <signal handler called>
#5 0x0000003fe7287084 in raise () from /lib64/lp64d/libc.so.6
#6 0x0000003fe8150cca in runtime.dieFromSignal (sig=sig@entry=6) at
../../../libgo/go/runtime/signal_unix.go:668
#7 0x0000003fe8150d42 in runtime.crash () at
../../../libgo/go/runtime/signal_unix.go:763
#8 0x0000003fe8155132 in runtime.fatalthrow () at
../../../libgo/go/runtime/panic.go:1072
#9 runtime.throw (s=...) at ../../../libgo/go/runtime/panic.go:1042
#10 0x0000003fe81551c4 in runtime.cgoCheckWriteBarrier..func1 () at
../../../libgo/go/runtime/cgocheck.go:55
#11 0x0000003fe814bf3e in runtime.systemstack..func1 (origg=0x3fbc000a80) at
../../../libgo/go/runtime/stubs.go:63
#12 0x0000003fe7e7376e in runtime_mstart (arg=<optimized out>) at
../../../libgo/runtime/proc.c:593
#13 0x0000000000035abe in main (argc=<optimized out>, argv=<optimized out>) at
../../../libgo/runtime/go-main.c:58
#14 0x0000003fe7277956 in __libc_start_main () from /lib64/lp64d/libc.so.6
#15 0x0000000000035afc in _start ()
My money is still on a buggy golang runtime.
Rich.
--
Richard Jones, Virtualization Group, Red Hat http://people.redhat.com/~rjones
Read my programming and virtualization blog: http://rwmj.wordpress.com
nbdkit - Flexible, fast NBD server with plugins
https://gitlab.com/nbdkit/nbdkit
1370
days inactive
1370
days old
12 comments
3 participants
participants (3)
-
Daniel P. Berrangé -
Nir Soffer -
Richard W.M. Jones