Image load failed

[John Leuner]

I pulled the latest git code, built the vm and then ran this image:

scratch/cslatevm/kernel.new.little.64.1232382035091548.image 3120520

...
Slate 1> Image saveNamed: 'slate.image'.
Saving image to slate.image
GC Freed 85463 words and coalesced 152 times
GC tenured 351 objects (3817 words)
Nil
Slate 2>
cmalu% ./slate slate.image
Old Memory size: 419430400 bytes
New Memory size: 10485760 bytes
Image size: 13113808 bytes
zsh: segmentation fault ./slate slate.image
cmalu% gdb --args ./slate slate.image
GNU gdb 6.7.1-debian
Copyright (C) 2007 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 "x86_64-linux-gnu"...
Using host libthread_db library "/lib/libthread_db.so.1".
(gdb) run
Starting program: /home/jewel/scratch/cslatevm/slate slate.image
[Thread debugging using libthread_db enabled]
Old Memory size: 419430400 bytes
New Memory size: 10485760 bytes
Image size: 13113808 bytes
[New Thread 0x7f20c252f6e0 (LWP 12618)]

Program received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7f20c252f6e0 (LWP 12618)]
0x00007f20c19b4fb5 in memcpy () from /lib/libc.so.6
(gdb) bt
#0 0x00007f20c19b4fb5 in memcpy () from /lib/libc.so.6
#1 0x0000000000409e73 in write_args_into ()
#2 0x000000000040e433 in prim_run_args_into ()
#3 0x00000000004077b8 in send_to_through_arity_with_optionals ()
#4 0x00000000004083b9 in interpret ()
#5 0x00000000004123b0 in main ()
(gdb)

Linux cmalu 2.6.26-1-amd64 #1 SMP Sat Jan 10 17:57:00 UTC 2009 x86_64
GNU/Linux
cmalu% gcc -v
Using built-in specs.
Target: x86_64-linux-gnu
Configured with: ../src/configure -v --with-pkgversion='Debian 4.3.1-2'
--with-bugurl=file:///usr/share/doc/gcc-4.3/README.Bugs
--enable-languages=c,c++,fortran,objc,obj-c++ --prefix=/usr
--enable-shared --with-system-zlib --libexecdir=/usr/lib
--without-included-gettext --enable-threads=posix --enable-nls
--with-gxx-include-dir=/usr/include/c++/4.3 --program-suffix=-4.3
--enable-clocale=gnu --enable-libstdcxx-debug --enable-objc-gc
--enable-mpfr --enable-cld --enable-checking=release
--build=x86_64-linux-gnu --host=x86_64-linux-gnu
--target=x86_64-linux-gnu
Thread model: posix
gcc version 4.3.1 (Debian 4.3.1-2)

John Leuner

[Timmy Douglas]

Thanks for the report. I've looked over the code and I'm not sure what
the problem is with prim_run_args_into/write_args_into. Perhaps you
could 'make vmclean && make DEBUG=1' (or zsh equivalent), start gdb
like you did, 'b write_args_into', and then print some of the
variables while stepping through that for loop? I just stepped through
it and the values look ok to me.

Breakpoint 1, write_args_into (oh=0x7f294aab4010,
buffer=0x7f29310b2958 "", limit=1024) at misc.c:134
134 nRemaining = limit;
(gdb) n
135 totalLen = 0;
(gdb)
136 for (i=0; i<oh->argcSaved; i++) {
(gdb) print oh->argcSaved
$1 = 2
(gdb) print oh->argvSaved[0]
$2 = 0x7fff53aef696 "/home/timmy/src/slate/cslatevm/slate"
(gdb) print oh->argvSaved[1]
$3 = 0x7fff53aef6bb "slate.image"
(gdb) n
137 iLen = strlen (oh->argvSaved [i]) + 1;
(gdb)
138 memcpy (buffer + totalLen, oh->argvSaved [i], max(iLen,
nRemaining));
(gdb)
139 totalLen += iLen;
(gdb)
141 nRemaining = max(nRemaining - iLen, 0);
(gdb)
136 for (i=0; i<oh->argcSaved; i++) {
(gdb)
137 iLen = strlen (oh->argvSaved [i]) + 1;
(gdb)
138 memcpy (buffer + totalLen, oh->argvSaved [i], max(iLen,
nRemaining));
(gdb)
139 totalLen += iLen;
(gdb)
141 nRemaining = max(nRemaining - iLen, 0);
(gdb)
136 for (i=0; i<oh->argcSaved; i++) {
(gdb)
143 return totalLen;
(gdb) print totalLen
$4 = 49
(gdb) print buffer
$5 = 0x7f29310b2958 "/home/timmy/src/slate/cslatevm/slate"
(gdb) x/100c buffer
0x7f29310b2958: 47 '/' 104 'h' 111 'o' 109 'm' 101 'e' 47 '/' 116
't' 105 'i'
0x7f29310b2960: 109 'm' 109 'm' 121 'y' 47 '/' 115 's' 114 'r' 99
'c' 47 '/'
0x7f29310b2968: 115 's' 108 'l' 97 'a' 116 't' 101 'e' 47 '/' 99
'c' 115 's'
0x7f29310b2970: 108 'l' 97 'a' 116 't' 101 'e' 118 'v' 109 'm' 47
'/' 115 's'
0x7f29310b2978: 108 'l' 97 'a' 116 't' 101 'e' 0 '\0' 115 's' 108
'l' 97 'a'
0x7f29310b2980: 116 't' 101 'e' 46 '.' 105 'i' 109 'm' 97 'a' 103
'g' 101 'e'
0x7f29310b2988: 0 '\0' 79 'O' 82 'R' 66 'B' 73 'I' 84 'T' 95
'_' 83 'S'
0x7f29310b2990: 79 'O' 67 'C' 75 'K' 69 'E' 84 'T' 68 'D' 73
'I' 82 'R'
0x7f29310b2998: 61 '=' 47 '/' 116 't' 109 'm' 112 'p' 47 '/' 111
'o' 114 'r'
0x7f29310b29a0: 98 'b' 105 'i' 116 't' 45 '-' 116 't' 105 'i' 109
'm' 109 'm'
0x7f29310b29a8: 121 'y' 0 '\0' 71 'G' 80 'P' 71 'G' 95 '_' 65
'A' 71 'G'
0x7f29310b29b0: 69 'E' 78 'N' 84 'T' 95 '_' 73 'I' 78 'N' 70
'F' 79 'O'
0x7f29310b29b8: 61 '=' 47 '/' 116 't' 109 'm'
(gdb) print limit
$6 = 1024

[John Leuner]

On Tue, 2009-02-03 at 15:30 -0800, Timmy Douglas wrote:
> make vmclean && make DEBUG=1

It fails when copying the first string

(gdb) run
The program being debugged has been started already.
Start it from the beginning? (y or n) y

Starting program: /home/jewel/scratch/cslatevm/slate slate.image
[Thread debugging using libthread_db enabled]
Old Memory size: 419430400 bytes
New Memory size: 10485760 bytes
Image size: 13113808 bytes

[New Thread 0x7f29db0f56e0 (LWP 15225)]
[Switching to Thread 0x7f29db0f56e0 (LWP 15225)]

Breakpoint 1, write_args_into (oh=0x7f29da0f9010, buffer=0x7f29c06f79f8

"", limit=1024) at misc.c:134
134 nRemaining = limit;
(gdb) n
135 totalLen = 0;

(gdb) n

136 for (i=0; i<oh->argcSaved; i++) {

(gdb) n
137 iLen = strlen (oh->argvSaved [i]) + 1;

(gdb) n

138 memcpy (buffer + totalLen, oh->argvSaved [i], max(iLen,
nRemaining));

(gdb) p iLen
$3 = 35
(gdb) p oh->argvSaved [i]
$4 = 0x7fffe3111d76 "/home/jewel/scratch/cslatevm/slate"
(gdb) x /100 buffer
0x7f29c06f79f8: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7a08: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7a18: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7a28: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7a38: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7a48: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7a58: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7a68: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7a78: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7a88: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7a98: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7aa8: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7ab8: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7ac8: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7ad8: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7ae8: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7af8: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7b08: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7b18: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7b28: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7b38: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7b48: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7b58: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7b68: 0x00000000 0x00000000 0x00000000
0x00000000
0x7f29c06f7b78: 0x00000000 0x00000000 0x00000000
0x00000000
(gdb) n

Program received signal SIGSEGV, Segmentation fault.

0x00007f29da57afb5 in memcpy () from /lib/libc.so.6
(gdb) bt
#0 0x00007f29da57afb5 in memcpy () from /lib/libc.so.6
#1 0x000000000040ce3a in write_args_into (oh=0x7f29da0f9010,
buffer=0x7f29c06f79f8 "/home/jewel/scratch/cslatevm/slate", limit=1024)
at misc.c:138
#2 0x0000000000413812 in prim_run_args_into (oh=0x7f29da0f9010,
args=0x7fffe31108a0, n=2, opts=0x0, resultStackPointer=22709) at
primitives.c:947
#3 0x00000000004089b5 in send_to_through_arity_with_optionals
(oh=0x7f29da0f9010, selector=0x7f29c13db5b8, args=0x7fffe31108a0,
dispatchers=0x7fffe31108a0, arity=2,
opts=0x0, resultStackPointer=22709) at interpreter.c:353
#4 0x0000000000409a1f in interpret (oh=0x7f29da0f9010) at
interpreter.c:708
#5 0x00000000004179b1 in main (argc=2, argv=0x7fffe3110c68) at vm.c:131

Is that resultStackPointer correct?

I also ran valgrind:

valgrind --tool=memcheck ./slate slate.image
==15150== Memcheck, a memory error detector.
==15150== Copyright (C) 2002-2007, and GNU GPL'd, by Julian Seward et
al.
==15150== Using LibVEX rev 1854, a library for dynamic binary
translation.
==15150== Copyright (C) 2004-2007, and GNU GPL'd, by OpenWorks LLP.
==15150== Using valgrind-3.3.1-Debian, a dynamic binary instrumentation
framework.
==15150== Copyright (C) 2000-2007, and GNU GPL'd, by Julian Seward et
al.
==15150== For more details, rerun with: -v
==15150==
==15150== Warning: set address range perms: large range 419430400
(undefined)

Old Memory size: 419430400 bytes
New Memory size: 10485760 bytes
Image size: 13113808 bytes

==15150== Invalid read of size 1
==15150== at 0x4C232B9: memcpy (mc_replace_strmem.c:402)
==15150== by 0x40CE39: write_args_into (misc.c:138)
==15150== by 0x413811: prim_run_args_into (primitives.c:947)
==15150== by 0x4089B4: send_to_through_arity_with_optionals
(interpreter.c:353)
==15150== by 0x409A1E: interpret (interpreter.c:708)
==15150== by 0x4179B0: main (vm.c:131)
==15150== Address 0x7ff001000 is not stack'd, malloc'd or (recently)
free'd
==15150==
==15150== Process terminating with default action of signal 11 (SIGSEGV)
==15150== Access not within mapped region at address 0x7FF001000
==15150== at 0x4C232B9: memcpy (mc_replace_strmem.c:402)
==15150== by 0x40CE39: write_args_into (misc.c:138)
==15150== by 0x413811: prim_run_args_into (primitives.c:947)
==15150== by 0x4089B4: send_to_through_arity_with_optionals
(interpreter.c:353)
==15150== by 0x409A1E: interpret (interpreter.c:708)
==15150== by 0x4179B0: main (vm.c:131)
==15150==
==15150== ERROR SUMMARY: 1 errors from 1 contexts (suppressed: 8 from 1)
==15150== malloc/free: in use at exit: 470,414,696 bytes in 10 blocks.
==15150== malloc/free: 10 allocs, 0 frees, 470,414,696 bytes allocated.
==15150== For counts of detected errors, rerun with: -v
==15150== searching for pointers to 10 not-freed blocks.
==15150== checked 20,177,856 bytes.
==15150==
==15150== LEAK SUMMARY:
==15150== definitely lost: 0 bytes in 0 blocks.
==15150== possibly lost: 0 bytes in 0 blocks.
==15150== still reachable: 470,414,696 bytes in 10 blocks.
==15150== suppressed: 0 bytes in 0 blocks.
==15150== Rerun with --leak-check=full to see details of leaked memory.
zsh: segmentation fault valgrind --tool=memcheck ./slate slate.image

John

[Timmy Douglas]

"Address 0x7ff001000"... Is that coming from the memcpy? Judging by
the backtrace, it copied the first argument into the buffer... but did
it overflow? The only difference in our gcc -v config options is that
you have enable-cld. While that might put a CLD instruction in your
memcpy, I don't think that it could cause anything like this.

We could eliminate the chance that it's an image error if you bzip
your image and email it to my google email. google at timmy.tmbx.com.

resultStackPointer looks fine.

maybe you could check the arguments to memcpy again to see if there is
a way something overflowed.

On Feb 4, 3:50 am, John Leuner <je...@subvert-the-dominant-

[John Leuner]

On Wed, 2009-02-04 at 17:31 -0800, Timmy Douglas wrote:
>
> "Address 0x7ff001000"... Is that coming from the memcpy? Judging by
> the backtrace, it copied the first argument into the buffer... but did
> it overflow? The only difference in our gcc -v config options is that
> you have enable-cld. While that might put a CLD instruction in your
> memcpy, I don't think that it could cause anything like this.

You mean in the valgrind trace? I guess that comes from the area where
valgrind allocated the buffer

> We could eliminate the chance that it's an image error if you bzip
> your image and email it to my google email. google at timmy.tmbx.com.

It fails with your image too

> resultStackPointer looks fine.
>
> maybe you could check the arguments to memcpy again to see if there is
> a way something overflowed.

Yes, it seems that 'buffer' is not big enough:

Breakpoint 1, write_args_into (oh=0x7f136251d010, buffer=0x7f1348b1b958

"", limit=1024) at misc.c:134
134 nRemaining = limit;
(gdb) n
135 totalLen = 0;
(gdb)

136 for (i=0; i<oh->argcSaved; i++) {
(gdb)

137 iLen = strlen (oh->argvSaved [i]) + 1;
(gdb)

138 memcpy ((void*) (buffer + totalLen), (void*) (oh->argvSaved
[i]), max(iLen, nRemaining));
(gdb) p totalLen
$4 = 0
(gdb) call memcpy(buffer + totalLen, oh->argvSaved[i], 512)
$5 = 1219606872
(gdb) call memcpy(buffer + totalLen, oh->argvSaved[i], 1000)

Program received signal SIGSEGV, Segmentation fault.

0x00007f136299efb5 in memcpy () from /lib/libc.so.6



John

[John Leuner]

After looking at the code:

word_t write_args_into(struct object_heap* oh, char* buffer, word_t
limit) {

word_t i, iLen, nRemaining, totalLen;

nRemaining = limit;
totalLen = 0;

for (i=0; i<oh->argcSaved; i++) {

iLen = strlen (oh->argvSaved [i]) + 1;

memcpy (buffer + totalLen, oh->argvSaved [i], max(iLen,
nRemaining));

totalLen += iLen;

nRemaining = max(nRemaining - iLen, 0);
}

return totalLen;

}


Using max(iLen,nRemaining) is incorrect because the argv string only has
iLen bytes

I think you want the minimum of iLen,nRemaining ... but a partial copy
is unacceptable isn't it? better to throw an error?

John

[Timmy Douglas]

Thanks for the catch. I'm going to commit some code that should get it
working for now.
The real fix would be to change this primitive to two primitives to
get argc and argv separately. That will wait for another day. Try the
latest changes from git.

I added an issue to fix the problem eventually.

http://code.google.com/p/slate-language/issues/detail?id=16