search

criblio / appscope

Gain observability into any Linux command or application with no code modification
https://appscope.dev
Apache License 2.0
266 stars 33 forks source link

AppScope trace logging level crashes processes #645

Closed jrcheli closed 2 years ago

jrcheli commented 2 years ago

LD_PRELOAD=lib/linux/x86_64/libscope.so SCOPE_LOG_LEVEL=trace ps -ef This segfaults on the master branch. (I happen to be running on an x86_64 on a glibc system)

michalbiesek commented 2 years ago

The issue can be reproduced even with a simple Hello world case:

#include <stdio.h>
int main() {
   printf("Hello, World");

   return 0;
}

SCOPE_LOG_LEVEL=trace ldscope ./main 
## we are not able to see "Hello world" message on stdout
echo $? 
## exit status should be 0 but it is equal 1

Reported Segfault is caused by stack overflow (see gdb --args ldscope ./main) Backtrace log:

#19495 0x00007ffff74b4835 in _IO_new_file_xsputn (n=67, data=<optimized out>, f=<optimized out>) at libioP.h:948
#19496 _IO_new_file_xsputn (f=0x5555555594a0, data=<optimized out>, n=67) at fileops.c:1197
#19497 0x00007ffff74a8541 in __GI__IO_fwrite (buf=0x7fffffffa660, size=1, count=67, fp=0x5555555594a0) at libioP.h:948
#19498 0x00007ffff76df7c5 in transportSend (trans=0x55555555c150, msg=0x7fffffffa660 "Scope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\n", len=67) at src/transport.c:1262
#19499 0x00007ffff76dfb13 in logSend (log=0x55555555c0d0, msg=0x7fffffffa660 "Scope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\n", mlevel=CFG_LOG_TRACE) at src/log.c:46
#19500 0x00007ffff76af1e9 in scopeLog (level=CFG_LOG_TRACE, format=0x7ffff7a2739d "fd:%d %s") at src/wrap.c:4866
#19501 0x00007ffff76b4e67 in doWrite (fd=999, initialTime=22989404688954, success=1, buf=0x55555555c530, bytes=132, func=0x7ffff7a261a0 "__write_libc", src=BUF, cnt=0) at src/state.c:2123
#19502 0x00007ffff76a40fc in __write_libc (fd=999, buf=0x55555555c530, size=132) at src/wrap.c:2596
#19503 0x00007ffff74b400d in _IO_new_file_write (f=0x5555555594a0, data=0x55555555c530, n=132) at fileops.c:1176
#19504 0x00007ffff74b5ad1 in new_do_write (to_do=132, data=0x55555555c530 "Scope: main(pid:40): [2021-11-25 14:07:46.096] fd:3 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main6.40\nclf1", fp=0x5555555594a0) at libioP.h:948
#19505 _IO_new_do_write (to_do=132, data=0x55555555c530 "Scope: main(pid:40): [2021-11-25 14:07:46.096] fd:3 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main6.40\nclf1", fp=0x5555555594a0) at fileops.c:426
#19506 _IO_new_do_write (fp=0x5555555594a0, data=0x55555555c530 "Scope: main(pid:40): [2021-11-25 14:07:46.096] fd:3 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main6.40\nclf1", to_do=132) at fileops.c:423
#19507 0x00007ffff74b4835 in _IO_new_file_xsputn (n=67, data=<optimized out>, f=<optimized out>) at libioP.h:948
#19508 _IO_new_file_xsputn (f=0x5555555594a0, data=<optimized out>, n=67) at fileops.c:1197
#19509 0x00007ffff74a8541 in __GI__IO_fwrite (buf=0x7fffffffba80, size=1, count=67, fp=0x5555555594a0) at libioP.h:948
#19510 0x00007ffff76df7c5 in transportSend (trans=0x55555555c150, msg=0x7fffffffba80 "Scope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\n", len=67) at src/transport.c:1262
#19511 0x00007ffff76dfb13 in logSend (log=0x55555555c0d0, msg=0x7fffffffba80 "Scope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\n", mlevel=CFG_LOG_TRACE) at src/log.c:46
#19512 0x00007ffff76af1e9 in scopeLog (level=CFG_LOG_TRACE, format=0x7ffff7a2739d "fd:%d %s") at src/wrap.c:4866
#19513 0x00007ffff76b4e67 in doWrite (fd=999, initialTime=22989404683103, success=1, buf=0x55555555c530, bytes=65, func=0x7ffff7a261a0 "__write_libc", src=BUF, cnt=0) at src/state.c:2123
#19514 0x00007ffff76a40fc in __write_libc (fd=999, buf=0x55555555c530, size=65) at src/wrap.c:2596
#19515 0x00007ffff74b400d in _IO_new_file_write (f=0x5555555594a0, data=0x55555555c530, n=65) at fileops.c:1176
#19516 0x00007ffff74b5ad1 in new_do_write (to_do=65, data=0x55555555c530 "Scope: main(pid:40): [2021-11-25 14:07:46.096] fd:3 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main6.40\nclf1", fp=0x5555555594a0) at libioP.h:948
#19517 _IO_new_do_write (to_do=65, data=0x55555555c530 "Scope: main(pid:40): [2021-11-25 14:07:46.096] fd:3 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main6.40\nclf1", fp=0x5555555594a0) at fileops.c:426
#19518 _IO_new_do_write (fp=0x5555555594a0, data=0x55555555c530 "Scope: main(pid:40): [2021-11-25 14:07:46.096] fd:3 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.096] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main(pid:40): [2021-11-25 14:07:46.097] fd:999 __write_libc\nScope: main6.40\nclf1", to_do=65) at fileops.c:423
#19519 0x00007ffff74b4835 in _IO_new_file_xsputn (n=65, data=<optimized out>, f=<optimized out>) at libioP.h:948
#19520 _IO_new_file_xsputn (f=0x5555555594a0, data=<optimized out>, n=65) at fileops.c:1197
#19521 0x00007ffff74a8541 in __GI__IO_fwrite (buf=0x7fffffffcea0, size=1, count=65, fp=0x5555555594a0) at libioP.h:948
#19522 0x00007ffff76df7c5 in transportSend (trans=0x55555555c150, msg=0x7fffffffcea0 "Scope: main(pid:40): [2021-11-25 14:07:46.096] fd:3 __write_libc\n", len=65) at src/transport.c:1262
#19523 0x00007ffff76dfb13 in logSend (log=0x55555555c0d0, msg=0x7fffffffcea0 "Scope: main(pid:40): [2021-11-25 14:07:46.096] fd:3 __write_libc\n", mlevel=CFG_LOG_TRACE) at src/log.c:46
#19524 0x00007ffff76af1e9 in scopeLog (level=CFG_LOG_TRACE, format=0x7ffff7a2739d "fd:%d %s") at src/wrap.c:4866
#19525 0x00007ffff76b4e67 in doWrite (fd=3, initialTime=22989404679599, success=1, buf=0x555555592880, bytes=60, func=0x7ffff7a261a0 "__write_libc", src=BUF, cnt=0) at src/state.c:2123
#19526 0x00007ffff76a40fc in __write_libc (fd=3, buf=0x555555592880, size=60) at src/wrap.c:2596
#19527 0x00007ffff74b400d in _IO_new_file_write (f=0x555555591170, data=0x555555592880, n=60) at fileops.c:1176
#19528 0x00007ffff74b5ad1 in new_do_write (to_do=60, data=0x555555592880 "  protect memory 0x7ffff7533000 (size=4096, prot=read,exec)\ne,exec) <- 0x7ffff75331d0 (size=5)\nsz=1000\n", fp=0x555555591170) at libioP.h:948
#19529 _IO_new_do_write (to_do=60, data=0x555555592880 "  protect memory 0x7ffff7533000 (size=4096, prot=read,exec)\ne,exec) <- 0x7ffff75331d0 (size=5)\nsz=1000\n", fp=0x555555591170) at fileops.c:426
#19530 _IO_new_do_write (fp=0x555555591170, data=0x555555592880 "  protect memory 0x7ffff7533000 (size=4096, prot=read,exec)\ne,exec) <- 0x7ffff75331d0 (size=5)\nsz=1000\n", to_do=60) at fileops.c:423
#19531 0x00007ffff74b35f8 in _IO_new_file_sync (fp=0x555555591170) at fileops.c:812
#19532 0x00007ffff74a7546 in __GI__IO_fflush (fp=0x555555591170) at libioP.h:948
#19533 0x00007ffff7762fdc in funchook_log () from /tmp/libscope-web/libscope.so
#19534 0x00007ffff77647c3 in funchook_unprotect_end () from /tmp/libscope-web/libscope.so
#19535 0x00007ffff776317a in funchook_install () from /tmp/libscope-web/libscope.so
#19536 0x00007ffff769c949 in initHook (attachedFlag=0) at src/wrap.c:1413
#19537 0x00007ffff769ce94 in init () at src/wrap.c:1557

With the interception of __write_libc we call doWrite and results in calling

https://github.com/criblio/appscope/blob/28c5f7b22b1e77a74011a51c29169f37fa271f50/src/state.c#L2123

Calling scope_log results in calling transportSend

https://github.com/criblio/appscope/blob/28c5f7b22b1e77a74011a51c29169f37fa271f50/src/transport.c#L1262

which results calling in __write_libc and cycle starts again results in a stack overflow.

As a reminder: Default Log destination path is file.

@jrcheli You will not observe segfault if you change the log destination path:

LD_PRELOAD=lib/linux/x86_64/libscope.so SCOPE_LOG_LEVEL=trace SCOPE_LOG_DEST=tcp://localhost:8125 ps -ef
michalbiesek commented 2 years ago

QA Instructions:

Observe that you will be able to see events and no segfault appeared during the following command:

LD_PRELOAD=libscope.so SCOPE_LOG_LEVEL=trace top
ledbit commented 2 years ago

365 seems similar in nature, maybe a similar approach/solution could be used there too.

jrcheli commented 2 years ago

I'm just capturing my thoughts while I review this...

At first glance, my worry is that this might not be a "general enough" solution... My concern was that transportSend() is calling g_fn.fwrite() which by our own policy should be "safe" (should not allow a reentrant path). So what's going on here that's special? The answer is that the "special part" is (that inside of initHook()) we're funchooking glibc's (and pthread's) __write function. So, even though we've been careful to avoid calling anything that we interpose in our library directly, the funchook is allowing us to still intercept our own g_fn.fwrite().

Generally we don't funchook things if we can avoid it. And I guess this is an example of why. So do we have any other paths that could be reentrant because we're funchooking them? I think we can get an answer to this by inspecting initHook(), where funchook is configured via funchook_prepare(). Here's the list of things that need consideration at this time: SSL_read -> (ok because ssl_read_hook is only use) SSL_write -> (ok because ssl_write_hook is only use) sendmmsg -> (ok because internal_sendmsg is only use) syscall -> (ok because scope_syscall is only use) sendto -> (ok because internal_sendto is only use) recvfrom -> (ok because internal_recvfrom is only use) uv_read -> (ok because uvread_hook is only use) __write_libc write_pthread

The implication is that if we call any of these specific g_fn functions during our own libscope behavior, it might be possible to cause a stack overflow in a similar manner to what has been described above. So I've included my analysis in parens of all of the other functions that need consideration right now. So I'm comfortable saying that at this time, write_libc and write_pthread are the only things we need to be worried about. The trick is that these are relatively hard to confirm that we've got these covered. Here's a list of places where we use g_fn.fwrite, outside of our interposed fwrite and fwrite_unlocked functions: contrib/libyaml/src/api.c in yaml_file_write_handler() src/transport.c in transportSent() src/wrap.c in remoteConfig() src/ctl.c in ctlFlushLog() I'm listing these just as an indication that we have the potential to cause similar problems. But I don't think this is comprehensive... as examples, any use of fprintf(), vfprintf(), dprintf(), or vdprintf() in our code seems like it could be a problem as well for the same reason, that they would probably end up in write_libc or write_pthread.

jrcheli commented 2 years ago

My conclusion right now is that I don't think this is the ideal general fix because of the way we're funchooking __write(). This is ok though, because I can't imagine any unintended side effects of this change, and in the immediate term this is a clear incremental improvement in the behavior (before this change, we'd crash when SCOPE_LOG_LEVEL=trace is set, and now we won't).

I think the long term ideal general fix would be to statically link in our own libc implementation and use it for everything our library does internally. This would allow us to separate the functionality of our library (here __write()) from functions which we are interposing from the host program where we're running. This is being investigated in #508 as "Approach 3", and is actively being worked on right now.