JS tracer fails on too large stacks in returnvalue

[holiman]

There appears to be a regression, which concerns alpine builds, which causes crashes like #23660 .
This seems to happen only when runing via docker, and it can be reproed like as shown below. This was once fixed by #22857, no idea why we're seeing it now.

Run it

docker run ethereum/client-go --nodiscover --maxpeers 0 --dev 

Also

docker exec -it beautiful_banach  /bin/sh

/ # geth attach /tmp/geth.ipc 
Welcome to the Geth JavaScript console!

instance: Geth/v1.10.10-unstable-f2491c5e/linux-amd64/go1.17.1
coinbase: 0xb2337989567fba76b5e50d8244c29aa38f33b2e3
at block: 0 (Thu Jan 01 1970 00:00:00 GMT+0000 (UTC))
 datadir: 
 modules: admin:1.0 clique:1.0 debug:1.0 eth:1.0 miner:1.0 net:1.0 personal:1.0 rpc:1.0 txpool:1.0 web3:1.0

To exit, press ctrl-d or type exit
> eth.sendTransaction({from:eth.accounts[0], to:eth.accounts[0], value:1 })
"0x1f1f731660e34a9e71bc8d2fe809334529ea8f6ce997d7fcdd34180c669d5c4f"

> tracer = "{step: function() {}, fault: function() {}, result: function() { var o={}; var x=o; for (var i=0; i<1000; i++){o.foo={}; o=o.foo; } return x; }}"
"{step: function() {}, fault: function() {}, result: function() { var o={}; var x=o; for (var i=0; i<1000; i++){o.foo={}; o=o.foo; } return x; }}"
> debug.traceTransaction("0x1f1f731660e34a9e71bc8d2fe809334529ea8f6ce997d7fcdd34180c669d5c4f", {"tracer": tracer})
Error: EOF
	at web3.js:6357:37(47)
	at web3.js:5091:62(37)
	at <eval>:1:23(7)

^ process killed.

[holiman]

tx = eth.sendTransaction({from:eth.accounts[0], to:eth.accounts[0], value: 1})


for(i = 0; i < 1000; i++){
        console.log("testing ", i)
        tracer = "{step: function() {}, fault: function() {}, result: function() { var o={}; var x=o; for (var i=0; i<"+i+"; i++){o.foo={}; o=o.foo; } return x; }}"
        debug.traceTransaction(tx, {"tracer": tracer})

}

It gets killed here:

testing  428
testing  429
GoError: Error while compiling or running script: Error: EOF at web3.js:6357:37(47)
	at native
	at <eval>:1:12(1)

[holiman]

backtrace courtesy of @gballet

#0  0x00007ffff7fb30b0 in printf_core (f=f@entry=0x0, 
    fmt=fmt@entry=0x18d9a3e "%p", ap=ap@entry=0x7fffccce70c0, 
    nl_arg=nl_arg@entry=0x7fffccce7150, nl_type=nl_type@entry=0x7fffccce70d8)
    at src/stdio/vfprintf.c:431
#1  0x00007ffff7fb3a3c in vfprintf (f=f@entry=0x7fffccce7248, 
    fmt=fmt@entry=0x18d9a3e "%p", ap=<optimized out>)
    at src/stdio/vfprintf.c:668
#2  0x00007ffff7fb5bbe in vsnprintf (s=s@entry=0x7fffccce7370 "", 
    n=n@entry=256, fmt=fmt@entry=0x18d9a3e "%p", ap=ap@entry=0x7fffccce7358)
    at src/stdio/vsnprintf.c:54
#3  0x00000000012a538f in duk__try_push_vsprintf (ap=0x7fffccce7358, 
    fmt=0x18d9a3e "%p", sz=256, buf=0x7fffccce7370, thr=0x7fffccce3070)
    at duk_api_stack.c:4765
#4  duk_push_vsprintf (thr=0x7fffccce3070, fmt=0x18d9a3e "%p", 
    ap=0x7fffccce74c0) at duk_api_stack.c:4817
#5  0x00000000012a5504 in duk_push_sprintf (thr=thr@entry=0x7fffccce3070, 
    fmt=fmt@entry=0x18d9a3e "%p") at duk_api_stack.c:4849
#6  0x00000000012befb4 in duk__enc_objarr_entry (js_ctx=0x7fffccd07480, 
    entry_top=0x7fffccce75f4) at duk_bi_json.c:1764
#7  0x00000000012c801e in duk__enc_object (js_ctx=0x7fffccd07480)
    at duk_bi_json.c:1833
#8  0x00000000012c7a9a in duk__enc_value (js_ctx=0x7fffccd07480, 
    idx_holder=1291) at duk_bi_json.c:2203

[holiman]

This same bug can be reproed all the way back to 1.9.1. I checked 1.8.1 too, that one crashes even earlier.

[gballet]

This problem is related to the musl libc library as much as to duktape. I am not a 100% sure what goes wrong just yet, but at the low level, duktape passes some invalid input to musl's vsnprintf function when trying to print a pointer.

The segfault is triggered in the prologue of musl's print_core. The function goes back on the stack, and it seems to go back too far, crossing a page boundary.

   0x00007ffff7fb309a <+0>:	push   %r15
   0x00007ffff7fb309c <+2>:	push   %r14
   0x00007ffff7fb309e <+4>:	push   %r13
   0x00007ffff7fb30a0 <+6>:	push   %r12
   0x00007ffff7fb30a2 <+8>:	push   %rbp
   0x00007ffff7fb30a3 <+9>:	mov    %rdi,%rbp
   0x00007ffff7fb30a6 <+12>:	push   %rbx
   0x00007ffff7fb30a7 <+13>:	xor    %ebx,%ebx
   0x00007ffff7fb30a9 <+15>:	sub    $0xa8,%rsp
   0x00007ffff7fb30b0 <+22>:	mov    %rdx,0x10(%rsp)

Before subtracting 0xa8, rsp is at 0x7fffd0ded070 and before executing the faulty mov %rdx,0x10(%rsp) instruction, rsp is at 0x7fffd0decfc0. The segfault is completely normal, since that new location is write(and read)-protected, unlike the stack page that vsnprintf is created with.

7fffd0deb000-7fffd0ded000 ---p 00000000 00:00 0 
7fffd0ded000-7fffd108e000 rw-p 00000000 00:00 0

So this is what happens at the very lowest level. Root cause analysis still needs to be done to understand why this came to be. The program is clearly running out of stack, as print_core is trying to allocate 168 bytes on a stack that it doesn't have. This problem doesn't occur on systems running a more standard libc (ran it on FreeBSD, the problem doesn't occur). The first conclusion I could reach is that the system needs more stack. I'll see if I can enforce that for duktape.

[gballet]

After increasing the thread stack size when linking-in duktape, the behavior is the expected one:

testing  997
testing  998
testing  999
{
  foo: {
    foo: {
      foo: {
        foo: {...}
      }
    }
  }
}

So that seems to be the problem: musl doesn't offer too much thread stack space (see here) for a nice comparison table. Because other distribs have a higher stack size, duktape usually hits the limit of 1000 allowed recursions before it runs out of stack. Not so with alpine linux, that offers a smaller stacksize by default.

[gballet]

@holiman Looks like go won't let me hardcode the linker flags to increase the stack size on alpine, so we have two courses of action to avoid this issue:

1. Reduce the maximum number of allowed recursions in duktape, possibly through a fork; or
2. Change build/ci.go to build geth with an increased stack size on alpine linux, as done in PR build: increase C thread stack size on linux #23676

[holiman]

Heh, that's pretty spot on: the table says 128KiB per thread. Well, we hit the error after roughty 430 nestings, and each nesting uses 256B stack buffer. 256 * 430 / 1024 = 107.5 KB, so taking some overhead into account, it looks like we're hitting exactly that limit.

[gballet]

429 to be precise

[holiman]

With that in mind, btw, it would be good if we could run the CI testsuite on alpine too.

[holiman]

Another alternative to 1), would be to fork duktape to not 'cheat' and use a stack buffer: https://github.com/svaarala/duktape/blob/master/src-input/duk_api_stack.c#L4768 , or make it smaller than 256 (https://github.com/svaarala/duktape/blob/master/src-input/duk_api_stack.c#L4737) . But it would decrease performance.

[holiman]

Would also be good to produce a minimum PoC and submit upstream to duktape, maybe they wouldn't mind figuring something out on their end.

[gballet]

Would also be good to produce a minimum PoC and submit upstream to duktape, maybe they wouldn't mind figuring something out on their end.

I thought about that, but Go doesn't let you set external ld flags via a #cgo directive. It has to be build externally 😠

[holiman]

I thought about that, but

I meant maybe just an alpine docker image with a minimal duktape interpreter which just loads a piece of code and crashes. Not sure what you mean is problematic?