parkhanbum / uftrace Goto Github PK

View Code? Open in Web Editor NEW

This project forked from namhyung/uftrace

1.0 1.0 0.0 7.19 MB

Function (graph) tracer for user-space

License: GNU General Public License v2.0

Makefile 1.77% C 77.11% Assembly 1.28% Shell 0.39% Batchfile 0.01% Python 18.50% C++ 0.57% Dockerfile 0.07% Lua 0.29%

uftrace's People

Contributors

Stargazers

Watchers

uftrace's Issues

dynamic tracing to already running process need pre-operation job.

we use ptrace to tracing already running process.
for this, we must do below command before using ptrace.

echo 0 | sudo tee /proc/sys/kernel/yama/ptrace_scope
/etc/sysctl.d/10-ptrace.conf kernel.yama.ptrace_scope = 0

full-dynamic test result

without libcapstone

211 replay_filter_C : OK OK OK OK OK OK OK OK OK OK
212 full_dyanmic : NZ NZ NZ NZ NZ NZ NZ NZ NZ NZ

runtime test stats

total 2120 Tests executed (success: 81.75%)
OK: 1670 Test succeeded
OK: 63 Test succeeded (with some fixup)
NG: 52 Different test result
NZ: 10 Non-zero return value
SG: 0 Abnormal exit by signal
TM: 0 Test ran too long
BI: 35 Build failed
LA: 0 Unsupported Language
SK: 290 Skipped

dynamic tracing method comparison.

[ORIGIN]
sleeping...7597
1525158868:667343
1525158868:667347
1525158868:667351
1525158868:667355
1525158868:667360
1525158869:683115
sleeping...7597
1525158869:683171
1525158869:683176
1525158869:683182
1525158869:683187
1525158869:683193
1525158870:699825

[LLDB-TRACE]
sleeping...7590
1525158825:85174
1525158825:110369
1525158825:134921
1525158825:156741
1525158825:181975
1525158826:219469
sleeping...7590
1525158826:250250
1525158826:273542
1525158826:296247
1525158826:319213
1525158826:339737
1525158827:386378

#update 
sleeping...3970
1526868698:338786
1526868698:346545
1526868698:349604
1526868698:352700
1526868698:355321
1526868699:355479
[DYNAMIC-INSTRUMENT]
sleeping...9411
1525159102:681405
1525159102:681408
1525159102:681410
1525159102:681413
1525159102:681414
1525159103:681698
sleeping...9411
1525159103:681707
1525159103:681710
1525159103:681712
1525159103:681714
1525159103:681715
1525159104:697067

nodejs에서 crash 가 발생하는 특수한 상황

nodejs는 자체적으로 polling을 한다.
mcount_entry / mcount_exit 에서 이뤄지는 작업이 지연될 경우
nodejs의 timeout 로직에 진입하게 된다
nodejs는 r15가 어떤 특별한 값이 보관된다고 예약이 되어 있고,
r15를 참조한 값을 rsp로 복원한 뒤 복귀하게 된다.

이때 mcount_entry / mcount_exit 에서 nodejs의 timeout 로직에 돌입하면
r15에 mtdp의 값을 적재된 상태로 복귀 로직을 타게 되고

잘못된 값이 rsp로 세팅되므로 이후 crash가 발생하게 된다.
이 과정을 살펴볼 수 있는 스크립트 로직은 다음과 같다.

set $count = 0
catch exec
commands
        set $s_rsp = 0

        br arch/x86_64/dynamic.S:45
        commands
        silent
                if *(unsigned long *)($rsp) == 0x00005555562ea385
                        set $count = $count + 1
                end
        continue
        end

        br arch/x86_64/dynamic.S:84
        commands
        silent
                set $s_rsp = $rsp
                if $count == 44
                        watch $r15 if $r15 == 0x7ffff7fb6760
                        watch $rsp if $rsp == 0x7ffff7fb6768
                end
        continue
        end

        br arch/x86_64/dynamic.S:87
        commands
        silent
                if *(unsigned long *)($rsp+0x48) < 0x20 && $s_rsp != $rsp
                        p "getcha"
                end
        continue
        end
continue
end

다음은 위 스크립츠로 찾아낸 문제 발생 지점이다.

Thread 2.1 "node" hit Watchpoint 6: $rsp

Old value = (void *) 0x7fffffffcdf0
New value = (void *) 0x7ffff7fb6768
0x000003ad1575be36 in ?? ()
(gdb) x/3i $rip-0x8
   0x3ad1575be2e:       mov    0x0(%rbp),%rbp
   0x3ad1575be32:       lea    0x8(%r15),%rsp
=> 0x3ad1575be36:       push   %rcx
(gdb) x/2i 0x3ad1575be32
   0x3ad1575be32:       lea    0x8(%r15),%rsp
=> 0x3ad1575be36:       push   %rcx
(gdb)

v8에서 crash가 발생하는 특수한 상황

v8에서 Interpreting 함수들에 Instrument 할 경우 특수한 crash가 발생한다.

d8> 1+1

Thread 2.1 "d8" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7ffff2d90840 (LWP 118815)]
0x00005555555bd9bc in std::__Cr::__loadword<unsigned long> (__p=0x7ffff5580038) at ../../buildtools/third_party/libc++/trunk/include/utility:978
978         std::memcpy(&__r, __p, sizeof(__r));
(gdb) bt
#0  0x00005555555bd9bc in std::__Cr::__loadword<unsigned long> (__p=0x7ffff5580038) at ../../buildtools/third_party/libc++/trunk/include/utility:978
#1  0x00005555555d6ced in v8::base::AsAtomicImpl<long>::Relaxed_Load<unsigned long> (addr=0x7ffff5580038) at ../../src/base/atomic-utils.h:78
#2  0x00005555555d6bed in v8::internal::FullObjectSlot::Relaxed_Load (this=0x7fffffffb840) at ../../src/objects/slots-inl.h:43
#3  0x00007ffff6c0d294 in v8::internal::MemoryChunk::HasHeaderSentinel (slot_addr=140737310097407) at ../../src/heap/spaces-inl.h:209
#4  0x00007ffff6c0d1e5 in v8::internal::MemoryChunk::FromAnyPointerAddress (addr=140737310097407) at ../../src/heap/spaces-inl.h:213
#5  0x00007ffff6c072e1 in v8::internal::PagedSpace::Contains (this=0x55555569b8e0, addr=140737349680485) at ../../src/heap/spaces-inl.h:164
#6  0x00007ffff6bfd305 in v8::internal::Heap::GcSafeFindCodeForInnerPointer (this=0x5555568a8fe8, inner_pointer=140737349680485) at ../../src/heap/heap.cc:5699
#7  0x00007ffff7bbfd65 in __dentry__ () at /home/m/git/uftrace/arch/x86_64/dynamic.S:114
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

문제 지점은 이곳이다.

0x00007ffff6bfd305 in v8::internal::Heap::GcSafeFindCodeForInnerPointer (this=0x5555568a8fe8, inner_pointer=140737349680485) at ../../src/heap/heap.cc:5699
(gdb) p/x inner_pointer
$1 = 0x7ffff7bbfd65
(gdb) x/gx 0x7ffff7bbfd65
0x7ffff7bbfd65 <dynamic_return>:        0x245c894c60ec8348

디버그용 검사 코드를 통해 문제 이유를 추정할 수 있다.

// src/heap/heap.cc:5699
DCHECK(code_space()->Contains(inner_pointer));

code_space 영역에서 inner_pointer를 찾을 수 있어야 하지만,
inner_pointer가 dynamic_return 주소이고 당연하게도 찾을 수 없으므로
crash를 발생하게 된다.

release용에서는 이 부분을 넘어가므로 원인 추적이 어렵다.

#0  0x0000555555bdcc1d in v8::internal::Sweeper::EnsurePageIsIterable(v8::internal::Page*) ()
#1  0x00007ffff7bbfd65 in __dentry__ () at /home/m/git/uftrace/arch/x86_64/dynamic.S:114
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

스택이 깨져 backtrace가 제대로 보이지 않으므로
디버깅용으로 넣은 mtdp iterating 함수를 호출하여 콜 스택을 살펴보자.

WARN: [48] [4] 0x7fffffffd4c0(value:0x7ffff7bbfe15)      0x7ffff7bbfe15  0x5555560b69c5
WARN: [49] [5] 0x7fffffffd498(value:0x5555560b6a02)      0x5555560b6a02  0x5555558a99a5
WARN: [50] [6] 0x7fffffffd468(value:0x5555558a99e8)      0x5555558a99e8  0x5555558ab3f5
WARN: [51] [18] 0x7fffffffd3d8(value:0x5555558abd59)     0x5555558abd59  0x5555558e0735
WARN: [52] [12] 0x7fffffffd378(value:0x5555558e0909)     0x5555558e0909  0x5555558dfec5
WARN: [53] [232] 0x7fffffffcc38(value:0x5555558e01be)    0x5555558e01be  0x555555b2f9c5
WARN: [54] [0] 0x7fffffffcc38(value:0x5555558e01be)      0x7ffff7bbfe15  0x555555b2fb95
WARN: [55] [32] 0x7fffffffcb38(value:0x555555b2fcdc)     0x555555b2fcdc  0x555555b30af5
WARN: [56] [0] 0x7fffffffcb38(value:0x555555b2fcdc)      0x7ffff7bbfe15  0x555555b30495
WARN: [57] [6] 0x7fffffffcb08(value:0x555555b3052d)      0x555555b3052d  0x555555b315b5
WARN: [58] [6] 0x7fffffffcad8(value:0x7ffff7bbfe15)      0x555555b3168e  0x555555b79865
WARN: [59] [8] 0x7fffffffca98(value:0x7ffff7bbfe15)      0x555555b798cd  0x555555bdcc15
(gdb) x/i 0x555555bdcc15
   0x555555bdcc15 <v8::internal::Sweeper::EnsurePageIsIterable(v8::internal::Page*)+5>: nop
(gdb) x/i 0x555555b79865
   0x555555b79865 <v8::internal::Heap::GcSafeFindCodeForInnerPointer(unsigned long)+5>: nop
(gdb) x/i 0x555555b315b5
   0x555555b315b5 <v8::internal::InnerPointerToCodeCache::GetCacheEntry(unsigned long)+5>:      nop
(gdb) x/i 0x555555b30495
   0x555555b30495 <v8::internal::StackFrame::ComputeType(v8::internal::StackFrameIteratorBase const*, v8::internal::StackFrame::State*)+5>:     nop
(gdb) x/i 0x555555b30af5
   0x555555b30af5 <v8::internal::StackFrame::GetCallerState(v8::internal::StackFrame::State*) const+5>: nop
(gdb) x/i 0x555555b2fb95
   0x555555b2fb95 <v8::internal::StackTraceFrameIterator::Advance()+5>: nop
(gdb) x/i 0x555555b2f9c5
   0x555555b2f9c5 <v8::internal::StackTraceFrameIterator::StackTraceFrameIterator(v8::internal::Isolate*)+5>:   nop
(gdb) x/i 0x5555558dfec5
   0x5555558dfec5 <v8::internal::Compiler::GetFunctionFromEval(v8::internal::Handle<v8::internal::String>, v8::internal::Handle<v8::internal::SharedFunctionInfo>, v8::internal::Handle<v8::internal::Context>, v8::internal::LanguageMode, v
8::internal::ParseRestriction, int, int, int)+5>:       nop
(gdb) x/i 0x5555558e0735
   0x5555558e0735 <v8::internal::Compiler::GetFunctionFromString(v8::internal::Handle<v8::internal::Context>, v8::internal::Handle<v8::internal::String>, v8::internal::ParseRestriction, int)+5>:      nop
(gdb) x/i 0x5555558ab3f5
   0x5555558ab3f5 <v8::internal::(anonymous namespace)::CreateDynamicFunction(v8::internal::Isolate*, v8::internal::BuiltinArguments, char const*)+5>:  nop

동일한 지점에서 문제가 발생한 것은 확인할 수 있다.
Debug에서 찾은 지점의 바로 다음 로직이다.

5699   DCHECK(code_space()->Contains(inner_pointer));
5700
5701   // Iterate through the page until we reach the end or find an object starting
5702   // after the inner pointer.
5703   Page* page = Page::FromAddress(inner_pointer);
5704   DCHECK_EQ(page->owner(), code_space());
5705   mark_compact_collector()->sweeper()->EnsurePageIsIterable(page);
5706
5707   Address addr = page->skip_list()->StartFor(inner_pointer);

실제로 문제가 발생하는 지점을 찾기 위해, dynamic_return의 주소가 v8의 로직을 오염시킨 지점을 추적해야 한다.

WARN: [21] [14] 0x7fffffffbae8(value:0x7ffff6b6c333)     0x7ffff6b6c333  0x7ffff6b6de95
WARN: [22] [6] 0x7fffffffbab8(value:0x7ffff6b6ded1)      0x7ffff6b6ded1  0x7ffff6b6d075
WARN: [23] [22] 0x7fffffffba08(value:0x7ffff6b6d2a5)     0x7ffff6b6d2a5  0x7ffff6b6dc65
WARN: [24] [6] 0x7fffffffb9d8(value:0x7ffff6b6dc85)      0x7ffff6b6dc85  0x7ffff6b6f6b5
WARN: [25] [12] 0x7fffffffb978(value:0x7ffff7bbfe15)     0x7ffff6b6f7d1  0x7ffff6bfd245
(gdb) x/i 0x7ffff6b6f6b5
   0x7ffff6b6f6b5 <v8::internal::InnerPointerToCodeCache::GetCacheEntry(unsigned long)+5>:      nop
(gdb) x/i 0x7ffff6b6dc65
   0x7ffff6b6dc65 <v8::internal::(anonymous namespace)::GetContainingCode(v8::internal::Isolate*, unsigned long)+5>: nop
(gdb) info line *0x7ffff6b6dc65
Line 414 of "../../src/frames.cc"
   starts at address 0x7ffff6b6dc60 <v8::internal::(anonymous namespace)::GetContainingCode(v8::internal::Isolate*, unsigned long)>
   and ends at 0x7ffff6b6dc70 <v8::internal::(anonymous namespace)::GetContainingCode(v8::internal::Isolate*, unsigned long)+16>.
(gdb) x/i 0x7ffff6b6d075
   0x7ffff6b6d075 <v8::internal::StackFrame::ComputeType(v8::internal::StackFrameIteratorBase const*, v8::internal::StackFrame::State*)+5>:   nop
(gdb) info line *0x7ffff6b6d075
Line 450 of "../../src/frames.cc"
   starts at address 0x7ffff6b6d070 <v8::internal::StackFrame::ComputeType(v8::internal::StackFrameIteratorBase const*, v8::internal::StackFrame::State*)>
   and ends at 0x7ffff6b6d087 <v8::internal::StackFrame::ComputeType(v8::internal::StackFrameIteratorBase const*, v8::internal::StackFrame::State*)+23>.
(gdb)

추적을 위해서는 디버깅 되는 버전이 최고다.

// src/frames.cc:480
 480     Address pc = *(state->pc_address);
 481     // If the {pc} does not point into WebAssembly code we can rely on the
 482     // returned {wasm_code} to be null and fall back to {GetContainingCode}.
 483     wasm::WasmCode* wasm_code =
 484         iterator->isolate()->wasm_engine()->code_manager()->LookupCode(pc);
 485     if (wasm_code != nullptr) {
 486       switch (wasm_code->kind()) {
 487         case wasm::WasmCode::kFunction:
 488           return WASM_COMPILED;
 489         case wasm::WasmCode::kWasmToJsWrapper:
 490           return WASM_TO_JS;
 491         case wasm::WasmCode::kLazyStub:
 492           return WASM_COMPILE_LAZY;
 493         case wasm::WasmCode::kRuntimeStub:
 494           return STUB;
 495         case wasm::WasmCode::kInterpreterEntry:
 496           return WASM_INTERPRETER_ENTRY;
 497         default:
 498           UNREACHABLE();
 499       }
 500     } else {
 501       // Look up the code object to figure out the type of the stack frame.
 502       Code code_obj = GetContainingCode(iterator->isolate(), pc);
 503       if (!code_obj.is_null()) {
 504         switch (code_obj->kind()) {

502번째 라인이 바로 우리가 찾던 문제의 시작점이다.
여기에 브포를 잡고 추적을 하면 언제 오염이 발생하는지 확인할 수 있다.

Thread 2.1 "d8" hit Breakpoint 2, v8::internal::StackFrame::ComputeType (iterator=0x7fffffffc1a8, state=0x7fffffffc0c0) at ../../src/frames.cc:502
502           Code code_obj = GetContainingCode(iterator->isolate(), pc);
(gdb) p *state
$1 = {sp = 140737488341616, fp = 140737488341776, pc_address = 0x7fffffffca68, callee_pc_address = 0x0, constant_pool_address = 0x0}
(gdb) p/x *state
$2 = {sp = 0x7fffffffca70, fp = 0x7fffffffcb10, pc_address = 0x7fffffffca68, callee_pc_address = 0x0, constant_pool_address = 0x0}
(gdb) x/gx 0x7fffffffca68
0x7fffffffca68: 0x00007ffff78957b2
(gdb) x/i 0x00007ffff78957b2
   0x7ffff78957b2 <Builtins_LdaGlobalHandler+28146>:    mov    r8,QWORD PTR [rbp-0x30]

정상적인 경우에는 위처럼 pc_address에는 interpreting function 주소가 위치해야 한다.

Thread 2.1 "d8" hit Breakpoint 2, v8::internal::StackFrame::ComputeType (iterator=0x7fffffffbfe8, state=0x7fffffffbb20) at ../../src/frames.cc:502
502           Code code_obj = GetContainingCode(iterator->isolate(), pc);
(gdb) p *state
$3 = {sp = 140737488341736, fp = 140737488341888, pc_address = 0x7fffffffcae0, callee_pc_address = 0x0, constant_pool_address = 0x0}
(gdb) p/x *state
$4 = {sp = 0x7fffffffcae8, fp = 0x7fffffffcb80, pc_address = 0x7fffffffcae0, callee_pc_address = 0x0, constant_pool_address = 0x0}
(gdb) x/gx 0x7fffffffcae0
0x7fffffffcae0: 0x00007ffff7bbfe15
(gdb) x/i 0x00007ffff7bbfe15
   0x7ffff7bbfe15 <dynamic_return>:     sub    rsp,0x60

하지만 보이다 싶이 오염이 발생한다... 이것은 v8에서 Interpreting 관련 logic이 독자 Stack frame 구조를 갖기 때문이다. 구체적으로 이번 케이스에서 마지막으로 mcount_return_fn의 주소 값으로 오염되는 곳은 다음과 같다.

Old value = 1143480881
New value = -138674667
0x00007ffff73ac1cc in Builtins_AdaptorWithBuiltinExitFrame () from /home/m/git/v8/v8/out.gn/x64.debug/./libv8.so
(gdb) disas
Dump of assembler code for function Builtins_AdaptorWithBuiltinExitFrame:
   0x00007ffff73ac1ac <+364>:   int3
   0x00007ffff73ac1ad <+365>:   mov    rcx,rax
   0x00007ffff73ac1b0 <+368>:   shl    rcx,0x20
   0x00007ffff73ac1b4 <+372>:   mov    rbp,QWORD PTR [rbp+0x0]
   0x00007ffff73ac1b8 <+376>:   mov    r10,QWORD PTR [rsp+0x18]
   0x00007ffff73ac1bd <+381>:   mov    QWORD PTR [rsp+0x28],r10
   0x00007ffff73ac1c2 <+386>:   mov    r10,QWORD PTR [rsp+0x38]
   0x00007ffff73ac1c7 <+391>:   mov    QWORD PTR [rsp+0x18],r10
=> 0x00007ffff73ac1cc <+396>:   mov    rbx,QWORD PTR [rsp+0x20]

(gdb) p/x $rsp+0x20
$3 = 0x7fffffffcae8

(gdb) call mcount_iterate_mtdp()
WARN: [IDX] [OFFSET] [PARENT_LOC](CURRENT_VALUE) [PARENT_VALUE](STORED) [CHILD]
WARN: [0] [0] 0x7fffffffd238(value:0x5555555c166c)       0x5555555c166c  0x7ffff6542c95
WARN: [1] [54] 0x7fffffffd088(value:0x7ffff6542f23)      0x7ffff6542f23  0x7ffff6b49875
WARN: [2] [20] 0x7fffffffcfe8(value:0x7ffff6b498df)      0x7ffff6b498df  0x7ffff6b498f5
WARN: [3] [112] 0x7fffffffcc68(value:0x7ffff6b4c58c)     0x7ffff6b4c58c  0x7ffff73bdcc5
WARN: [4] [13] 0x7fffffffcc00(value:0x7ffff73bdd38)      0x7ffff73bdd38  0x7ffff73bdf65
WARN: [5] [5] 0x7fffffffcbd8(value:0x7ffff73bdfbd)       0x7ffff73bdfbd  0x7ffff73c85c5
WARN: [6] [9] 0x7fffffffcb90(value:0x7ffff73c8988)       0x7ffff73c8988  0x7ffff73c8a65
WARN: [7] [1] 0x7fffffffcb88(value:0x7ffff7bbfe15)       0x7ffff7bbfe15  0x7ffff73c85c5
WARN: [8] [14] 0x7fffffffcb18(value:0x7ffff73c8988)      0x7ffff73c8988  0x7ffff73c8a65
WARN: [9] [3] 0x7fffffffcb00(value:0x7ffff7bbfe15)       0x7ffff7bbfe15  0x7ffff73ac225
WARN: [10] [0] 0x7fffffffcb00(value:0x7ffff7bbfe15)      0x7ffff7bbfe15  0x7ffff74ef945
WARN: [11] [0] 0x7fffffffcb00(value:0x7ffff7bbfe15)      0x7ffff7bbfe15  0x7ffff73ac045

이번 케이스에서 마지막일뿐, 위에서 확인할 수 있듯이 실제 stack과 mtdp의 rstack은 두 가지 방향으로 지속적으로 오염되고 있음을 알 수 있다.

동일한 Parent_location에서 중복되는 mcount_entry의 호출이 이뤄진다.
=> mtdp rstack에는 지속적으로 mcount_return_fn으로 hook된 parent_loc의 저장이 일어난다.
동일한 Parent_location에서 중복되는 mcount_exit의 호출이 이뤄진다.
=> 지속적으로 mcount_return_fn으로 stack을 복구한다.

이런 문제로 uftrace는 v8의 interpreting logic에서 관리하는 stack을 오염시키게 되고,
이는 최초에 확인한 내용처럼 code objects들에 포함되지 않는 mcount_return_fn이 javascript frames에 존재하게 되어 crash를 발생하게 되는 것이다.

this is why we add 2 to freespaceaddr.

Breakpoint 3, main (argc=4, argv=0x7fffffffe3f8) at inject-x86_64.c:254
254             ptrace_write(target, addr, newcode, injectSharedLibrary_size);
(gdb) p/x addr
$3 = 0x400008
(gdb) p/x newcode
$4 = 0x6054c0
(gdb) x/i 0x6054c0
   0x6054c0:    push   %rbp
(gdb) x/20i 0x6054c0
   0x6054c0:    push   %rbp
   0x6054c1:    mov    %rsp,%rbp
   0x6054c4:    mov    %rdi,-0x8(%rbp)
   0x6054c8:    mov    %rsi,-0x10(%rbp)
   0x6054cc:    mov    %rdx,-0x18(%rbp)
   0x6054d0:    push   %rsi
   0x6054d1:    push   %rdx
   0x6054d2:    push   %r9
   0x6054d4:    mov    %rdi,%r9
   0x6054d7:    mov    %rcx,%rdi
   0x6054da:    callq  *%r9
   0x6054dd:    pop    %r9
   0x6054df:    int3
   0x6054e0:    pop    %rdx
   0x6054e1:    push   %r9
   0x6054e3:    mov    %rdx,%r9
   0x6054e6:    mov    %rax,%rdi
   0x6054e9:    movabs $0x1,%rsi
   0x6054f3:    callq  *%r9
   0x6054f6:    pop    %r9
(gdb) x/10x 0x6054c0
0x6054c0:       0xe5894855      0xf87d8948      0xf0758948      0xe8558948
0x6054d0:       0x51415256      0x48f98949      0xff41cf89      0xcc5941d1
0x6054e0:       0x4951415a      0x8948d189

disassemble of injectSharedLibrary

(gdb) disas injectSharedLibrary
Dump of assembler code for function injectSharedLibrary:
   0x0000000000401a20 <+0>:     push   %rbp
   0x0000000000401a21 <+1>:     mov    %rsp,%rbp
   0x0000000000401a24 <+4>:     mov    %rdi,-0x8(%rbp)
   0x0000000000401a28 <+8>:     mov    %rsi,-0x10(%rbp)
   0x0000000000401a2c <+12>:    mov    %rdx,-0x18(%rbp)
   0x0000000000401a30 <+16>:    push   %rsi
   0x0000000000401a31 <+17>:    push   %rdx
   0x0000000000401a32 <+18>:    push   %r9
   0x0000000000401a34 <+20>:    mov    %rdi,%r9
   0x0000000000401a37 <+23>:    mov    %rcx,%rdi
   0x0000000000401a3a <+26>:    callq  *%r9
   0x0000000000401a3d <+29>:    pop    %r9
   0x0000000000401a3f <+31>:    int3
   0x0000000000401a40 <+32>:    pop    %rdx
   0x0000000000401a41 <+33>:    push   %r9
   0x0000000000401a43 <+35>:    mov    %rdx,%r9
   0x0000000000401a46 <+38>:    mov    %rax,%rdi
   0x0000000000401a49 <+41>:    movabs $0x1,%rsi
   0x0000000000401a53 <+51>:    callq  *%r9
   0x0000000000401a56 <+54>:    pop    %r9
   0x0000000000401a58 <+56>:    int3
   0x0000000000401a59 <+57>:    mov    %rax,%rdi
   0x0000000000401a5c <+60>:    pop    %rsi
   0x0000000000401a5d <+61>:    push   %rbx
   0x0000000000401a5e <+62>:    mov    %rsi,%rbx
   0x0000000000401a61 <+65>:    xor    %rsi,%rsi
   0x0000000000401a64 <+68>:    int3
   0x0000000000401a65 <+69>:    callq  *%rbx
   0x0000000000401a67 <+71>:    pop    %rbx
   0x0000000000401a68 <+72>:    pop    %rbp
   0x0000000000401a69 <+73>:    retq
End of assembler dump.

Breakpoint 1, main (argc=4, argv=0x7fffffffe3f8) at inject-x86_64.c:213
213             regs.rip = addr + 2;
(gdb) p/x addr
$1 = 0x400008
(gdb)

Guard Recursion

Dump of assembler code for function wi::shifted_mask(long*, unsigned int, unsigned int, bool, unsigned int):
   0x0000000000c65c10 <+0>:     callq  *0x10caf5a(%rip)        # 0x1d30b70
   0x0000000000c65c16 <+6>:     nop

0000000000c65c10 <_ZN2wi12shifted_maskEPljjbj>:
  c65c10:       44 39 c6                cmp    %r8d,%esi
  c65c13:       44 0f b6 c9             movzbl %cl,%r9d
  c65c17:       0f 83 b3 00 00 00       jae    c65cd0 <_ZN2wi12shifted_maskEPljjbj+0xc0>

mcount-dynamic: dynamic_entry 7fffa19aed98, c65c16, 7fffa19aed10
mcount-dynamic: ============  DISASM ================
mcount-dynamic: 0xc65c10[06]:call qword ptr [rip + 0x10caf5a]
mcount-dynamic: =====================================
mcount: [mod: 7f2c4196e168, idx: 83] enter 595ec0: free
mcount: <8> enter 595ec0
mcount:  tr->flags: 0, filter mode, count: [0] 0/0
mcount: [83] exit  7f2c40cbe4f0: free
mcount: <9> exit  595ec0
mcount: task 14331 recorded 48 bytes (record count = 3)
mcount: rstack[7] ENTRY c65d76
mcount: rstack[8] ENTRY 595ec0
mcount: rstack[8] EXIT  595ec0
mcount: [mod: 7f2c4196e168, idx: 83] enter 595ec0: free
mcount: <8> enter 595ec0
mcount:  tr->flags: 0, filter mode, count: [0] 0/0
mcount: [83] exit  7f2c40cbe4f0: free
mcount: <9> exit  595ec0
mcount: task 14331 recorded 32 bytes (record count = 2)
mcount: rstack[8] ENTRY 595ec0
mcount: rstack[8] EXIT  595ec0
mcount: <8> enter c65c16
mcount:  tr->flags: 0, filter mode, count: [0] 0/0
mcount-dynamic: Let's find original code :  0
mcount-dynamic: c65c10 matched -  c65c10
mcount-dynamic: Address : c65c10 224d7c60
mcount: <9> exit  c65c16
mcount: task 14331 recorded 32 bytes (record count = 2)
mcount: rstack[8] ENTRY c65c16
mcount: rstack[8] EXIT  c65c16
mcount-dynamic: dynamic_entry 7fffa19ae7a8, 10f3de6, 7fffa19ae720
mcount-dynamic: ============  DISASM ================
mcount-dynamic: 0x10f3de0[06]:call qword ptr [rip + 0xc3cd8a]
mcount-dynamic: =====================================
mcount: Guard recursion!

(gdb) bt
#0  0x00007f38c3d25a3e in mcount_entry (parent_loc=0x7ffd455741a8, child=17776102, regs=0x7ffd45574120)
    at /home/m/git/_uftrace/libmcount/mcount.c:836
#1  0x00007f38c3d298d0 in dynamic_entry (parent_loc=0x7ffd455741a8, child=17776102, regs=0x7ffd45574120)
    at /home/m/git/_uftrace/libmcount/mcount-dynamic.c:466
#2  0x00007f38c3d4291f in __dentry__ () at /home/m/git/_uftrace/arch/x86_64/dynamic_hook.S:86
#3  0x0000000000000081 in ?? ()
#4  0x0000000001337226 in ?? ()
#5  0x00007f38c35d58ae in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#6  0x00007ffd455747a0 in ?? ()
#7  0x000000000000000b in ?? ()
#8  0x000000000000000b in ?? ()
#9  0x00007f38c380d920 in ?? () from /lib/x86_64-linux-gnu/libc.so.6
#10 0x0000000000000002 in ?? ()
#11 0x0000000000000000 in ?? ()
(gdb) print* (struct mcount_thread_data *) 0x7f38c415b728
$6 = {tid = 15356, idx = 8, record_idx = 8, recursion_marker = true, in_exception = false, cygprof_dummy = 0, rstack = 0x1,
  argbuf = 0x7f38c4059010, filter = {in_count = 0, out_count = 0, depth = 1016, saved_depth = 1016, time = 0, saved_time = 0},
  enable_cached = true, shmem = {seqnum = 747, losts = 0, curr = 0, nr_buf = 2, max_buf = 2, done = false, buffer = 0x2207d00}, event = {{
      time = 0, id = 0, dsize = 0, idx = 0, data = '\000' <repeats 1007 times>}, {time = 0, id = 0, dsize = 0, idx = 0,
      data = '\000' <repeats 1007 times>}, {time = 0, id = 0, dsize = 0, idx = 0, data = '\000' <repeats 1007 times>}, {time = 0, id = 0,
      dsize = 0, idx = 0, data = '\000' <repeats 1007 times>}}, nr_events = 0, arch = {xmm = {0, 0, 0, 0, 0, 0, 0, 0}}}

testcase in symbol.c

1114:bug : [waitpid start] 804b150 < [add_map] 604f4 < [waitpid end] 804b160
1115:fail : [waitpid start] 804b150 < [add_map] 604f4 < [waitpid end] 804b160
1116:bug : [strsep start] 804b140 < [add_map] 604f4 < [strsep end] 804b150
1117:fail : [strsep start] 804b140 < [add_map] 604f4 < [strsep end] 804b150

mcount_find_code does not store registers from r12 to r15

the Functions written by assembly and customized have highly possibility to cause problem.

This case associated with _start function.

symptom

This is the state of the register saved to using as mcount_regs when it reaches main.

CASE : uftrace record -L. tests/t-fibonacci

mcount: mcount_entry 7ffebd565a38, 40077e, 7ffebd565a00
mcount: RDI : 2
mcount: RSI : 7ffebd565b18
mcount: RDX : 7ffebd565b30
mcount: RCX : 1a05ff0
mcount: R8 : 0
mcount: R9 : 30

CASE : uftrace dynamic -L. tests/t-fibonacci

dynamic_entry 7ffdba227760, 4005f6, 7ffdba227728
mcount: mcount_entry 7ffdba227760, 4005f6, 7ffdba227728
mcount: RDI : 3d8a6168
mcount: RSI : 1
mcount: RDX : 7f1e3d68fab0
mcount: RCX : 7ffdba227778
mcount: R8 : 7f1e3d8a66f8
mcount: R9 : 0
mcount: mcount_thread_data
mcount: MOUNT INIT
mcount: new session started: 6a4da7db4a64f21f: t-fibonacci
mcount: found patched address : 4005f0
mcount: Address : 4005f0 14daff0
mcount: PLTHOOK ENTRY :
mcount: dynamic_entry 7ffdba227688, 400816, 7ffdba227650
mcount: mcount_entry 7ffdba227688, 400816, 7ffdba227650
mcount: RDI : 3d46be89
mcount: RSI : 7ffdba227768
mcount: RDX : 146fff0
mcount: RCX : a0
mcount: R8 : 400880
mcount: R9 : 7f1e3d68fab0
mcount: found patched address : 400810
mcount: Address : 400810 14db260
mcount: PLTHOOK ENTRY :
mcount: PLTHOOK ENTRY :
mcount: [mcount_exit] : 7ffdba227670
mcount: mcount_entry 7ffdba227688, 40077e, 7ffdba227650
mcount: RDI : 3d46be89
mcount: RSI : 7ffdba227768
mcount: RDX : 146fff0
mcount: RCX : 0
mcount: R8 : 1
mcount: R9 : 60

the RDI register must contain count of arguments at normally. you can see it from "record case". at "record case", RDI have contained number "2". but at "dynamic case", RDI have contained randomize value as abnormally.

Diagnosis

the reason is because '_start' function highly customized and do not make frame-point. see _start function prologue. at dynamic tracing, before we discover the problem, there was no reason to exclude the '_start' function.

  4005f0:       31 ed                   xor    %ebp,%ebp
  4005f2:       49 89 d1                mov    %rdx,%r9
  4005f5:       5e                      pop    %rsi

but third instruction of _start function have popped the stack without any interaction.
only we can do that guessing there is some implicit step to use RSI register as argument count.

problem occured here.

mcount: [0] 4005f0  42 :  _start

mcount: DISASM:
mcount: 0xf1cff0[02]:xor ebp, ebp
mcount: 0xf1cff2[03]:mov r9, rdx
mcount: 0xf1cff5[01]:pop rsi
mcount: 0xf1cff6[06]:jmp qword ptr [rip]

mcount: DISASM:
mcount: 0x4005f0[06]:call qword ptr [rip + 0x200a0a]

after some instruction at _start function head have changed to call instruction, it call the dentry pre-called function before calling the mcount_entry. in this situlation, we handle top of the stack value as "child" which mean return address. this is problem, it is not the return address but the "argument count" to popped from stack to RSI.

for that reason, stack have polluted and cannot execute normally. if program use the argument count like test fibonacci. I think the same thing will happen while uftrace use cases increase.

Prescription

for now, exclude _start function.

Future TASK

So we have to remember that this case is very important. and we must improve logic to detect same mechanism.

gcc does not store for r12~15 when optimizing flag has setted 0.

if uftrace made with DEBUG=1 flag, gcc did not made codes for preserve the register from r12 to r15.

'make test' is broken

'make test' does not work because there is the new dependency.
we must fix makefile to make it correctly for new dependency.

v8 javascript tracing

As mentioned earlier, it is very useful to use the metadata provided by the tracing target.
Tracing the execution of Javascript in v8 is possible with the -trace option.

you can see this result with -trace option.

$ node -trace test3.js > trace.log

$ cat test3.js
function find_me_c() {
    console.log("=======================================================Hello c");
}
function find_me_b() {
    find_me_c();
    console.log("=======================================================Hello b");
}
function find_me_a() {
    find_me_b();
    console.log("=======================================================Hello a");
}

function find_me_A() {
    console.log("=======================================================Hello A");
}
function find_me_B() {
    console.log("=======================================================Hello B");
}
function find_me_C() {
    console.log("=======================================================Hello C");
}

find_me_a();
find_me_b();
find_me_c();

find_me_A();
find_me_B();
find_me_C();

  10:          ~find_me_a+0(this=0x097043e04de9 <JSGlobal Object>) {
  11:           ~find_me_b+0(this=0x097043e04de9 <JSGlobal Object>) {
  12:            ~find_me_c+0(this=0x097043e04de9 <JSGlobal Object>) {
  13:             ~log+3(this=0x391efb18ab59 <Object map = 0x1eeeeefd2521>) {

how this be possible?
This is because v8 adds the following code when converting javascript to bytecode:

[generated bytecode for function: find_me_a]
Parameter count 1
Frame size 24
         0x2842eda4ab12 @    0 : 5e c1 01 fb 00    CallRuntime [TraceEnter], r0-r0
  313 E> 0x2842eda4ab17 @    5 : a1                StackCheck
  322 S> 0x2842eda4ab18 @    6 : 1b 05             LdaImmutableCurrentContextSlot [5]
         0x2842eda4ab1a @    8 : 26 fb             Star r0
  322 E> 0x2842eda4ab1c @   10 : 5a fb 00          CallUndefinedReceiver0 r0, [0]
  339 S> 0x2842eda4ab1f @   13 : 13 00 02          LdaGlobal [0], [2]
         0x2842eda4ab22 @   16 : 26 fa             Star r1
  347 E> 0x2842eda4ab24 @   18 : 28 fa 01 04       LdaNamedProperty r1, [1], [4]
         0x2842eda4ab28 @   22 : 26 fb             Star r0
         0x2842eda4ab2a @   24 : 12 02             LdaConstant [2]
         0x2842eda4ab2c @   26 : 26 f9             Star r2
  347 E> 0x2842eda4ab2e @   28 : 57 fb fa f9 06    CallProperty1 r0, r1, r2, [6]
         0x2842eda4ab33 @   33 : 0d                LdaUndefined
         0x2842eda4ab34 @   34 : 26 fb             Star r0
         0x2842eda4ab36 @   36 : 5e c2 01 fb 01    CallRuntime [TraceExit], r0-r0
  418 S> 0x2842eda4ab3b @   41 : a5                Return
Constant pool (size = 3)
0x2842eda4aa91: [FixedArray] in OldSpace
 - map: 0x121960b028b9 <Map>
 - length: 3
           0: 0x139ba9693ca1 <String[7]: console>
           1: 0x139ba96852b9 <String[3]: log>
           2: 0x2842eda4a9d1 <String[62]: =======================================================Hello a>

This is the key to enabling tracing.

         0x2842eda4ab12 @    0 : 5e c1 01 fb 00    CallRuntime [TraceEnter], r0-r0
         0x2842eda4ab36 @   36 : 5e c2 01 fb 01    CallRuntime [TraceExit], r0-r0

And here is the source code for this.

RUNTIME_FUNCTION(Runtime_TraceEnter) {
JavaScriptFrame::PrintTop(isolate, stdout, true, false);

void JavaScriptFrame::PrintTop(Isolate* isolate, FILE* file, bool print_args,
                               bool print_line_number) {
  JavaScriptFrameIterator it(isolate);
  while (!it.done()) {
    if (it.frame()->is_java_script()) {
      JavaScriptFrame* frame = it.frame();
      if (frame->IsConstructor()) PrintF(file, "new ");
      JSFunction* function = frame->function();
      int code_offset = 0;
      if (frame->is_interpreted()) {
        InterpretedFrame* iframe = reinterpret_cast<InterpretedFrame*>(frame);
        code_offset = iframe->GetBytecodeOffset();
      } else {
        Code* code = frame->unchecked_code();
        code_offset = static_cast<int>(frame->pc() - code->InstructionStart());
      }
      PrintFunctionAndOffset(function, function->abstract_code(), code_offset,
                             file, print_line_number);

so, With the data provided by v8, you can easily trace the execution of Javascript.
I wrote a simple piece of code to demonstrate the proof of concept.

/* keep extern tracing data */
FILE* extern_data;
extern_data = fopen("extern.dat", "w+");

static int js_fn_index = 1;

// mcount_entry_filter_record
           if (!(rstack->flags & MCOUNT_FL_NORECORD)) {
                 mtdp->record_idx++;
                 if (!strcmp(tr->name, "v8::internal::JavaScriptFrame::PrintTop")) {
                         pr_dbg("[JS_FN_IN] v8::internal::JavaScriptFrame::PrintTop\n");
                         char fin[128] = {0};
                         uint64_t ts = mcount_gettime();
                         snprintf(fin, sizeof(fin), "\n%10ld.%09ld %4d:%*s JS_FN_CALL ",
                                         ts / NSEC_PER_SEC, ts % NSEC_PER_SEC,
                                         js_fn_index, js_fn_index*1, "");
                         js_fn_index++;
                         fwrite(fin, sizeof(char), strlen(fin), extern_data);
                         ARG2(regs) = (uintptr_t)extern_data;
                 }

                 if (!strcmp(tr->name, "v8::internal::Runtime_TraceExit")) {
                         pr_dbg("[JS_FN_OUT] v8::internal::Runtime_TraceExit\n");
                         char fin[128] = {0};
                         uint64_t ts = mcount_gettime();

                         js_fn_index--;
                         snprintf(fin, sizeof(fin), "\n%10ld.%09ld %4d:%*s } -> JS_FN_RET ",
                                         ts / NSEC_PER_SEC, ts % NSEC_PER_SEC,
                                         js_fn_index, js_fn_index*1, "");

                         fwrite(fin, sizeof(char), strlen(fin), extern_data);
                 }

The function "v8 :: internal :: JavaScriptFrame :: PrintTop" writes the JavaScript function name and arguments to the second argument "FILE *" that is passed when called. I replaced it with a file pointer in the "extern.dat" file, which I wrote separately.

now, do tracing the nodejs with uftrace.

$ ./uftrace record -v -L. --auto-arg  ../node_pg/node_g -trace ../node/test3-1.js
$ grep "find_me" -nR extern.dat
5171:    569444.136595365   10:           JS_FN_CALL ~find_me_a+0(this=0x27c8b4284de9 <JSGlobal Object>)                                                     5172:    569444.137504866   11:            JS_FN_CALL ~find_me_b+0(this=0x27c8b4284de9 <JSGlobal Object>)                                                    5173:    569444.138305860   12:             JS_FN_CALL ~find_me_c+0(this=0x27c8b4284de9 <JSGlobal Object>)                                                   5423:    569444.348092897   10:           JS_FN_CALL ~find_me_b+0(this=0x27c8b4284de9 <JSGlobal Object>)
5424:    569444.348319676   11:            JS_FN_CALL ~find_me_c+0(this=0x27c8b4284de9 <JSGlobal Object>)                                                    5591:    569444.407940002   10:           JS_FN_CALL ~find_me_c+0(this=0x27c8b4284de9 <JSGlobal Object>)                                                     5675:    569444.439317732   10:           JS_FN_CALL ~find_me_A+0(this=0x391c1b458699 <Object map = 0x1394c89ce651>)                                         5759:    569444.469558980   10:           JS_FN_CALL ~find_me_B+0(this=0x391c1b458699 <Object map = 0x1394c89ce651>)                                         5843:    569444.499600839   10:           JS_FN_CALL ~find_me_C+0(this=0x391c1b458699 <Object map = 0x1394c89ce651>)                                         5927:    569444.528369390   10:           JS_FN_CALL ~find_me_A+0(this=0x391c1b458699 <Object map = 0x1394c89ce651>)
6011:    569444.557419714   10:           JS_FN_CALL ~find_me_B+0(this=0x391c1b458699 <Object map = 0x1394c89ce651>)                                         6095:    569444.586947622   10:           JS_FN_CALL ~find_me_C+0(this=0x391c1b458699 <Object map = 0x1394c89ce651>)
6179:    569444.618293920   10:           JS_FN_CALL ~find_me_A+0(this=0x27c8b4284de9 <JSGlobal Object>)                                                     6263:    569444.648832028   10:           JS_FN_CALL ~find_me_B+0(this=0x27c8b4284de9 <JSGlobal Object>)                                                     6347:    569444.676890141   10:           JS_FN_CALL ~find_me_C+0(this=0x27c8b4284de9 <JSGlobal Object>)

its done. Now it is time to copy extern.dat to uftrace.data and try replaying.

$ ./uftrace replay -f +time > node_replay
$ grep "find_me" -nR node_replay
22321933:            [  5117]   569444.136595365 | /* external-data: 10:           JS_FN_CALL ~find_me_a+0(this=0x27c8b4284de9 <JSGlobal Object>) */

find_me_a calls find_me_b and you can see this process by cutting it.

$ sed -n 22321933,22325878p node_replay > find_me_a_calls_find_me_b
$ cat find_me_a_calls_find_me_b | wc -l
3946

just one function call, but Calling a function is really complicated!!
Let's just look at the first and last lines.

[  5117]   569444.136595365 | /* external-data: 10:           JS_FN_CALL ~find_me_a+0(this=0x27c8b4284de9 <JSGlobal Object>) */
[  5117]   569444.137504866 | /* external-data: 11:            JS_FN_CALL ~find_me_b+0(this=0x27c8b4284de9 <JSGlobal Object>) */

This is a trick to tracing javascript execution through the -trace option provided by v8.
how do you think?

v8에서 crash가 발생하는 특수한 상황 #2

앞에서 본 문제가 발생하는 것을 막기 위해 심플한 검증 로직을 추가하여,
RET에 주소가 실행가능한 영역이 아닌 경우에는 복귀주소 후킹을 하지 못하도록
코드를 추가했다.

하지만 이런 검증 로직에도 불구하고 여전히 문제가 발생하는데,
이 또한 역시 v8의 interpreting 로직의 특수성 때문이다.

문제가 발생하는 곳은 다음의 함수이다.

Dump of assembler code for function Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit:
0x00007ffff772ee24 <+100>:   mov    rcx,QWORD PTR [rbp+0x8]                                                                                                                                                                                  0x00007ffff772ee28 <+104>:   mov    rbp,QWORD PTR [rbp+0x0]                                                                                                                                                                                  0x00007ffff772ee2c <+108>:   lea    rsp,[r15+0x8]                                                                                                                                                                                            0x00007ffff772ee30 <+112>:   push   rcx                                                                                                                                                                                                   => 0x00007ffff772ee31 <+113>:   mov    rsi,QWORD PTR [r13+0x2f78]

설명에 앞서 rcx에 적재되는 값의 주소는

Thread 2.1 "d8" hit Breakpoint 5, 0x00007ffff772ee24 in Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit () from /home/m/git/v8/v8/out.gn/x64.debug/./libv8.so
$1 = 0x7fffffffcac8

0x7fffffffcac8 + 0x8 = 0x7fffffffcad0 이다.

왜 문제가 발생하는지 설명하자면,

0x00007ffff772ee24 <+100>:   mov    rcx,QWORD PTR [rbp+0x8]                                                                                                                                                                                  0x00007ffff772ee28 <+104>:   mov    rbp,QWORD PTR [rbp+0x0]

이곳에서 복귀주소를 읽어,
다음 명령을 통해

0x00007ffff772ee30 <+112>:   push   rcx

stack에 push하고 return한다.

0x00007ffff772ee38 <+120>:   mov    QWORD PTR [r13+0x2f78],0x1                                                                                                                                                                               0x00007ffff772ee43 <+131>:   mov    QWORD PTR [r13+0x2fd0],0x0                                                                                                                                                                               0x00007ffff772ee4e <+142>:   ret

이 때 call stack은 uftrace에 의해 hooking 된 주소가 들어가 있다.

(gdb) call mcount_iterate_mtdp()
WARN: [IDX] [OFFSET] [PARENT_LOC](CURRENT_VALUE) [PARENT_VALUE](STORED) [CHILD]
WARN: [0] [0] 0x7fffffffcc18(value:0x7ffff6b4b58c)       0x7ffff6b4b58c  0x7ffff73bccc5
WARN: [1] [13] 0x7fffffffcbb0(value:0x7ffff73bcd38)      0x7ffff73bcd38  0x7ffff73bcf65
WARN: [2] [5] 0x7fffffffcb88(value:0x7ffff73bcfbd)       0x7ffff73bcfbd  0x7ffff73c75c5
WARN: [3] [23] 0x7fffffffcad0(value:0x7ffff7bbf4a3)      0x7ffff78faa1c  0x7ffff772edc5

(gdb) x/i 0x7ffff772edc5
   0x7ffff772edc5 <Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit+5>: nop

(gdb) p/x mtd->rstack[3]
$2 = {parent_loc = 0x7fffffffcad0, parent_ip = 0x7ffff78faa1c, child_ip = 0x7ffff772edc5, flags = 0x40, start_time = 0x216c8623942d9, end_time = 0x0, tid = 0x0, dyn_idx = 0xefefefef, filter_time = 0x0, depth = 0x3,
  filter_depth = 0x3fd, nr_events = 0x0, event_idx = 0x400, pd = 0x0, pargs = 0x0}

(gdb) x/i 0x7ffff73c75c5
   0x7ffff73c75c5 <Builtins_InterpreterEntryTrampoline+5>:      nop

호출은 Builtins_InterpreterEntryTrampoline -> Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit 순으로 이뤄지며, Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit 함수에서는 Builtins_InterpreterEntryTrampoline 의 리턴주소를 읽어들여 stack에 push하고 리턴하게 된다.

이것은 동일한 함수에서 이뤄지기 때문에, uftrace 입장에서는 정상적인 동작이나 v8에서는 그렇지 않다.

support Non-hook-RET options

uftrace hope that functions follow the calling convention. but there is an exception like nodejs case. so, it is added restore-reset mechanism to uftrace. it still needs more precision.

I have two exceptional cases in v8 interpreter that uftrace crashed on.

reuse stack frame
v8 interpreter check the code objects which exist in javascript stack frame for some purpose. v8 interpreter use its own stack frame because it want to not affect to C stack frame. so, stack base frame does not changed in v8 interpreter logic. in this case, while v8 interpreter check the javascript stack frame, it find weird value mcount_return_fn that has been instrumented by uftrace. and occure crash.

let's see followed case:

d8> 1+1

Thread 2.1 "d8" received signal SIGSEGV, Segmentation fault.
[Switching to Thread 0x7ffff2d90840 (LWP 118815)]
0x00005555555bd9bc in std::__Cr::__loadword<unsigned long> (__p=0x7ffff5580038) at ../../buildtools/third_party/libc++/trunk/include/utility:978
978         std::memcpy(&__r, __p, sizeof(__r));
(gdb) bt
#0  0x00005555555bd9bc in std::__Cr::__loadword<unsigned long> (__p=0x7ffff5580038) at ../../buildtools/third_party/libc++/trunk/include/utility:978
#1  0x00005555555d6ced in v8::base::AsAtomicImpl<long>::Relaxed_Load<unsigned long> (addr=0x7ffff5580038) at ../../src/base/atomic-utils.h:78
#2  0x00005555555d6bed in v8::internal::FullObjectSlot::Relaxed_Load (this=0x7fffffffb840) at ../../src/objects/slots-inl.h:43
#3  0x00007ffff6c0d294 in v8::internal::MemoryChunk::HasHeaderSentinel (slot_addr=140737310097407) at ../../src/heap/spaces-inl.h:209
#4  0x00007ffff6c0d1e5 in v8::internal::MemoryChunk::FromAnyPointerAddress (addr=140737310097407) at ../../src/heap/spaces-inl.h:213
#5  0x00007ffff6c072e1 in v8::internal::PagedSpace::Contains (this=0x55555569b8e0, addr=140737349680485) at ../../src/heap/spaces-inl.h:164
#6  0x00007ffff6bfd305 in v8::internal::Heap::GcSafeFindCodeForInnerPointer (this=0x5555568a8fe8, inner_pointer=140737349680485) at ../../src/heap/heap.cc:5699
#7  0x00007ffff7bbfd65 in __dentry__ () at /home/m/git/uftrace/arch/x86_64/dynamic.S:114
Backtrace stopped: previous frame inner to this frame (corrupt stack?)

v8 interpreter crashed on here:

0x00007ffff6bfd305 in v8::internal::Heap::GcSafeFindCodeForInnerPointer (this=0x5555568a8fe8, inner_pointer=140737349680485) at ../../src/heap/heap.cc:5699
(gdb) p/x inner_pointer
$1 = 0x7ffff7bbfd65
(gdb) x/gx 0x7ffff7bbfd65
0x7ffff7bbfd65 <dynamic_return>:        0x245c894c60ec8348

source codes :

// src/heap/heap.cc:5699
DCHECK(code_space()->Contains(inner_pointer));

v8 interpreter could not found the address of mcount_return_fn from its code object pool, obviously.

this is normal case:

Thread 2.1 "d8" hit Breakpoint 2, v8::internal::StackFrame::ComputeType (iterator=0x7fffffffc1a8, state=0x7fffffffc0c0) at ../../src/frames.cc:502
502           Code code_obj = GetContainingCode(iterator->isolate(), pc);
(gdb) p *state
$1 = {sp = 140737488341616, fp = 140737488341776, pc_address = 0x7fffffffca68, callee_pc_address = 0x0, constant_pool_address = 0x0}
(gdb) p/x *state
$2 = {sp = 0x7fffffffca70, fp = 0x7fffffffcb10, pc_address = 0x7fffffffca68, callee_pc_address = 0x0, constant_pool_address = 0x0}
(gdb) x/gx 0x7fffffffca68
0x7fffffffca68: 0x00007ffff78957b2
(gdb) x/i 0x00007ffff78957b2
   0x7ffff78957b2 <Builtins_LdaGlobalHandler+28146>:    mov    r8,QWORD PTR [rbp-0x30]

see belowed instructions.

Old value = 1143480881
New value = -138674667
0x00007ffff73ac1cc in Builtins_AdaptorWithBuiltinExitFrame () from /home/m/git/v8/v8/out.gn/x64.debug/./libv8.so
(gdb) disas
Dump of assembler code for function Builtins_AdaptorWithBuiltinExitFrame:
   0x00007ffff73ac1ac <+364>:   int3
   0x00007ffff73ac1ad <+365>:   mov    rcx,rax
   0x00007ffff73ac1b0 <+368>:   shl    rcx,0x20
   0x00007ffff73ac1b4 <+372>:   mov    rbp,QWORD PTR [rbp+0x0]
   0x00007ffff73ac1b8 <+376>:   mov    r10,QWORD PTR [rsp+0x18]
   0x00007ffff73ac1bd <+381>:   mov    QWORD PTR [rsp+0x28],r10
   0x00007ffff73ac1c2 <+386>:   mov    r10,QWORD PTR [rsp+0x38]
   0x00007ffff73ac1c7 <+391>:   mov    QWORD PTR [rsp+0x18],r10
=> 0x00007ffff73ac1cc <+396>:   mov    rbx,QWORD PTR [rsp+0x20]

(gdb) p/x $rsp+0x20
$3 = 0x7fffffffcae8

(gdb) call mcount_iterate_mtdp()
WARN: [IDX] [OFFSET] [PARENT_LOC](CURRENT_VALUE) [PARENT_VALUE](STORED) [CHILD]
WARN: [0] [0] 0x7fffffffd238(value:0x5555555c166c)       0x5555555c166c  0x7ffff6542c95
WARN: [1] [54] 0x7fffffffd088(value:0x7ffff6542f23)      0x7ffff6542f23  0x7ffff6b49875
WARN: [2] [20] 0x7fffffffcfe8(value:0x7ffff6b498df)      0x7ffff6b498df  0x7ffff6b498f5
WARN: [3] [112] 0x7fffffffcc68(value:0x7ffff6b4c58c)     0x7ffff6b4c58c  0x7ffff73bdcc5
WARN: [4] [13] 0x7fffffffcc00(value:0x7ffff73bdd38)      0x7ffff73bdd38  0x7ffff73bdf65
WARN: [5] [5] 0x7fffffffcbd8(value:0x7ffff73bdfbd)       0x7ffff73bdfbd  0x7ffff73c85c5
WARN: [6] [9] 0x7fffffffcb90(value:0x7ffff73c8988)       0x7ffff73c8988  0x7ffff73c8a65
WARN: [7] [1] 0x7fffffffcb88(value:0x7ffff7bbfe15)       0x7ffff7bbfe15  0x7ffff73c85c5
WARN: [8] [14] 0x7fffffffcb18(value:0x7ffff73c8988)      0x7ffff73c8988  0x7ffff73c8a65
WARN: [9] [3] 0x7fffffffcb00(value:0x7ffff7bbfe15)       0x7ffff7bbfe15  0x7ffff73ac225
WARN: [10] [0] 0x7fffffffcb00(value:0x7ffff7bbfe15)      0x7ffff7bbfe15  0x7ffff74ef945
WARN: [11] [0] 0x7fffffffcb00(value:0x7ffff7bbfe15)      0x7ffff7bbfe15  0x7ffff73ac045

as you can see, v8 interpreter working on same stack frame.

direct accessing previous RET
v8 interpreter does not follow calling convention as mention at first case. sometime v8 interpreter access previous stack frame directly. this used for read function arguments at normal case. but v8 interpreter access previous stack frame directly for read RET. this is not allowed in calling convention. in this time, mcount_return_fn address will be exist in RET because uftrace hook the RET to mcount_return_fn in reset function. so, v8 will crashed on.

problem occurred at here:

Dump of assembler code for function Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit:
0x00007ffff772ee24 <+100>:   mov    rcx,QWORD PTR [rbp+0x8]                                                                                                                                                                                  0x00007ffff772ee28 <+104>:   mov    rbp,QWORD PTR [rbp+0x0]                                                                                                                                                                                  0x00007ffff772ee2c <+108>:   lea    rsp,[r15+0x8]                                                                                                                                                                                            0x00007ffff772ee30 <+112>:   push   rcx                                                                                                                                                                                                   => 0x00007ffff772ee31 <+113>:   mov    rsi,QWORD PTR [r13+0x2f78]

value that keep in rcx register:

Thread 2.1 "d8" hit Breakpoint 5, 0x00007ffff772ee24 in Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit () from /home/m/git/v8/v8/out.gn/x64.debug/./libv8.so
$1 = 0x7fffffffcac8

so, rcx has 0x7fffffffcac8 + 0x8 = 0x7fffffffcad0.
let's see what value has stored in 0x7fffffffcad0.

(gdb) call mcount_iterate_mtdp()
WARN: [IDX] [OFFSET] [PARENT_LOC](CURRENT_VALUE) [PARENT_VALUE](STORED) [CHILD]
WARN: [0] [0] 0x7fffffffcc18(value:0x7ffff6b4b58c)       0x7ffff6b4b58c  0x7ffff73bccc5
WARN: [1] [13] 0x7fffffffcbb0(value:0x7ffff73bcd38)      0x7ffff73bcd38  0x7ffff73bcf65
WARN: [2] [5] 0x7fffffffcb88(value:0x7ffff73bcfbd)       0x7ffff73bcfbd  0x7ffff73c75c5
WARN: [3] [23] 0x7fffffffcad0(value:0x7ffff7bbf4a3)      0x7ffff78faa1c  0x7ffff772edc5

(gdb) x/i 0x7ffff772edc5
   0x7ffff772edc5 <Builtins_CEntry_Return1_DontSaveFPRegs_ArgvOnStack_NoBuiltinExit+5>: nop

(gdb) p/x mtd->rstack[3]
$2 = {parent_loc = 0x7fffffffcad0, parent_ip = 0x7ffff78faa1c, child_ip = 0x7ffff772edc5, flags = 0x40, start_time = 0x216c8623942d9, end_time = 0x0, tid = 0x0, dyn_idx = 0xefefefef, filter_time = 0x0, depth = 0x3,
  filter_depth = 0x3fd, nr_events = 0x0, event_idx = 0x400, pd = 0x0, pargs = 0x0}

(gdb) x/i 0x7ffff73c75c5
   0x7ffff73c75c5 <Builtins_InterpreterEntryTrampoline+5>:      nop

mcount_exit 에서 r15를 복원하지 않아 crash 발생

디버깅을 위해 -fno-inline 옵션을 주고 컴파일을 했을 시
mcount_exit는 r15를 복원하지 않으며 이로 인해 이후
crash가 발생하게 된다.

대상 software : node v10.16.0

prevent selecting uftrace path

m@m:/git/prevent$ which uftrace record -v --data=pwd/xxx tests/t-abc
uftrace: dirname : /home/m/git/prevent/xxx, /usr/local/bin/uftrace, /home/m/git/prevent/xxxuftrace: /home/m/git/prevent/utils/utils.c:222:create_directory
ERROR: DO NOT REACH HERE!: No such file or directory
m@m:/git/prevent$

overflow in symbolc.

symbol: [1] d 10000202c + 4 called.4160
symbol: [2] d 100002030 + 1 completed.7209
symbol: [3] t 10000059b + 21 a
symbol: [4] t 1000005b0 + 21 b
symbol: [5] t 1000005c5 + 51 c
symbol: [6] T 1000006b0 + 2 __libc_csu_fini
symbol: [7] T 1000006c0 + 52 atexit
symbol: [8] T 100000490 + 75 gmon_start
symbol: [9] D 10000070c + 4 _IO_stdin_used
symbol: [10] T 100000650 + 93 __libc_csu_init
symbol: [11] D 100000708 + 4 _fp_hw
symbol: [12] T 1000005f8 + 85 main

Dynamic tracing feature will not work when use with --keep-pid option.

sometime using uftrace with dynamic feature does not work correctly,
if use --keep-pid option.

maybe this issue associate with timing issue or not.

call/jump with IMM value can supported, if we re-calculate IMM value.

for now, we can not support call/jump with IMM value because IMM values are relative.
if we can calculate IMM value runtime and replace original IMM, then we can support call/jump instruction for dynamic feature.

plthooker cause recursive calling, if attach to target process that was running already.

Core was generated by `./node_g simple_server.js'.
Program terminated with signal SIGSEGV, Segmentation fault.
#0  0x00007f255c03becb in plthook_entry (ret_addr=0x7f255ca66078, child_idx=282, module_id=88480016,
    regs=0x7f255ca66038) at /home/m/git/attaching/libmcount/plthook.c:686
686             struct uftrace_trigger tr = {
[Current thread is 1 (Thread 0x7f255d265700 (LWP 106896))]
(gdb) bt
#0  0x00007f255c03becb in plthook_entry (ret_addr=0x7f255ca66078, child_idx=282, module_id=88480016,
    regs=0x7f255ca66038) at /home/m/git/attaching/libmcount/plthook.c:686
#1  0x00007f255c050b2e in plt_hooker () at /home/m/git/attaching/arch/x86_64/plthook.S:40
#2  0x00007f255edd56e9 in _dl_update_slotinfo (req_modid=4) at ../elf/dl-tls.c:714
#3  0x00007f255edd587c in update_get_addr (ti=0x7f255c260fc8) at ../elf/dl-tls.c:799
#4  0x00007f255eddba28 in __tls_get_addr () at ../sysdeps/x86_64/tls_get_addr.S:55
#5  0x00007f255c03542d in mcount_prepare () at /home/m/git/attaching/libmcount/mcount.c:531
#6  0x00007f255c03c26b in plthook_entry (ret_addr=0x7f255ca66268, child_idx=282, module_id=88480016,
    regs=0x7f255ca66228) at /home/m/git/attaching/libmcount/plthook.c:714
Backtrace stopped: previous frame identical to this frame (corrupt stack?)

if we try to attach to process that was running already, then crash has been occurred, as you can see. this is because plt function "free" has been called recursive while proceed the plthook_entry function.

why "free@plt" plt function was called in plthook_entry function as recursive? this is associate with "how refer thread local storage in libmcount.so".

uftrace refer thread local storage in function plthook_entry to read mcount_thread_data. doing refer the thread local storage will calling function __tls_get_addr to find address which allocated to current thread. this is not harmful to general use-case that doing hook by using LD_PRELOAD.

but when we try attaching to already running process, they already been initialized the thread local storage. so, there is some differently work doing in __tls_get_addr to expand or to reduce DTV size.

in ../elf/dl-tls.c:714
714               free (dtv[modid].pointer.to_free);

while doing this, it will cause recusive calling in plthook_entry.