debugging node.js regarding recover (written by Namhyung)

[honggyukim]

node.js 에 ftrace를 적용하는 과정에서 몇 가지 문제점을 확인하였는데, 이를 디버깅 하는 과정의 삽질기를 간략하게 정리하여 이 페이지에 기록함. 테스트를 위해 사용한 프로그램은 아주 단순히 콘솔에 Hello world 를 출력하는 1줄 짜리 스크립트 였음.

문제점

최초로 의심했던 부분은 libmcount 에서 리턴 주소를 바꿔치는 하는 부분에서 잘못된 접근이 발생할 가능성이었음. 이를 확인하기 위해 mcount entry/exit 에서 리턴 주소가 저장되는 위치를 확인하여 그 주소가 mismatch 되는 부분이 있는지 검사. 그러나 결과적으로 문제가 없었던 것으로 확인.

다음으로 mcount entry에서 리턴 주소 주변의 스택값을 저장해두었다가 mcount exit 시 해당 값이 변경되었는지 확인하기로 함. 그 결과 값이 변경되는 경우가 수 차례 발견되었으나, 이는 스택에 객체를 할당한 뒤 포인터를 전달하여 이를 변경하는 정상적인 접근이었던 것으로 확인됨.

다음으로 코드 생성 자체가 문제가 있어서 mcount 진입 시 잘못된 리턴 주소가 넘어오는 것이 아닌지 확인하기로 함. 이를 위해 python 스크립트를 작성하여 각 함수 별 objdump의 디스어셈블리 결과를 일일이 확인하여 mcount 호출 전에 스택프레임이 정상적으로 설정되는지 검사하도록 하였음. 실행 결과는 아래와 같음

$ time ./validator.py node-pg
...
 
   SUMMARY
=============
/home/namhyung/tmp/ftrace/node-pg: 10216 good, 9 bad, 1865 tailcall, 2204 skipped, 276 unknown
 
real    67m26.358s
user    60m53.796s
sys     7m40.887s
 
$ grep 'frame pointer' tmp/ftrace/result-validation.txt | grep -v tail
deregister_tm_clones: return with frame pointer.
register_tm_clones: return with frame pointer.
AES_encrypt: return with frame pointer.
AES_decrypt: return with frame pointer.
AES_cbc_encrypt: return with frame pointer.
Camellia_Ekeygen: return with frame pointer.
sha1_block_data_order_ssse3: return with frame pointer.
whirlpool_block: return with frame pointer.
__libc_csu_init: return with frame pointer.

검사 결과 총 9개의 함수에서 frame pointer 설정이 올바르게 되어있지 않다고 보고하였으나, 해당 함수들은 대부분 어셈블리로 직접 작성된 함수들이어서 mcount 함수로 진입하지 않으므로 실질적인 문제가 되지는 않는다고 판단됨. (역시 컴파일러가 문제일리는 없었다는 ... ;;; )

다음으로 의심한 것은 tailcall 최적화였음. 확인 결과 C++ 프로그램들은 많은 small function들로 이루어져 있으며 이들은 많은 경우 inlining 및 tailcall 최적화가 적용되어 있음. tailcall 최적화가 적용되는 경우 함수 진입이 call instruction 이 아닌 jmp instruction 을 통해 이루어지므로 mcount 가 관리하는 return stack이 꼬일 가능성이 있다고 의심하였음. 예를 들어 다음과 같이 함수 호출이 이루어짐.

0000000000607370 <_register_async_wrap>:
  607370:       55                      push   %rbp
  607371:       48 89 e5                mov    %rsp,%rbp
  607374:       e8 c7 e9 ff ff          callq  605d40 <mcount@plt>
  607379:       5d                      pop    %rbp
  60737a:       bf a0 6c 24 01          mov    $0x1246ca0,%edi
  60737f:       e9 9c 70 5a 00          jmpq   bae420 <node_module_register>
  607384:       66 2e 0f 1f 84 00 00    nopw   %cs:0x0(%rax,%rax,1)
  60738b:       00 00 00
  60738e:       66 90                   xchg   %ax,%ax

이 경우 _register_async_wrap 함수가 호출되어 mcount를 부르고 다시 frame pointer를 원상 복귀한 뒤 jmp를 통해 node_module_register 함수로 진입하였음. 이제 node_module_register 함수 내에서도 mcount 함수를 호출하므로 리턴 주소가 덮어써짐! 그리고 return 실행 시 mcount_return이 두 번 실행되지 않고 한 번만 실행될 것이므로 stack idx가 불일치할 가능성이 있음.

하지만 확인 결과 덮어써지는 리턴 주소는 mcount_return이 되기 때문에 이를 다시 복구하는 과정에서 mcount_return이 한 번 더 불리고 최종적으로 정상 실행되는 것을 확인하였음. 따라서 이미 ftrace가 tailcall 의 경우도 잘 처리하고 있었음. 이 디버깅 과정에서 tailcall 인지 확인하기 위해 리턴 주소가 저장되는 포인터를 비교하여 tailcall 인 경우 그냥 mcount 함수를 skip 하도록 테스트해 보았는데 node.js 가 정상적으로 실행되었음. 하지만 확인 결과 이는 tailcall 검사를 수행하는 조건문에 있던 오류로 인해 대부분의 경우 mcount 함수가 실행되지 않았기 때문이었음. 조건문을 정상적으로 수정하였더니 tailcall 여부와 상관없이 프로그램이 정상적으로(question) 비정상 종료됨.

해결 과정

장기전으로 돌입하기 위해 -pg 없이 빌드한 node와 -pg 를 주고 빌드한 node를 따로 gdb를 물려서 실행되는 과정을 비교. 확인 결과 정상적인 경우 Heap::ReserveSpace() 함수 내에서 Heap::CollecctGarbage() 함수 자체가 호출되지 않음. 해당 함수는 다음과 같음.

void Heap::ReserveSpace(int* sizes, Address* locations_out) {
  bool gc_performed = true;
  int counter = 0;
  static const int kThreshold = 20;
  while (gc_performed && counter++ < kThreshold) {
    gc_performed = false;
    DCHECK(NEW_SPACE == FIRST_PAGED_SPACE - 1);
    for (int space = NEW_SPACE; space <= LAST_PAGED_SPACE; space++) {
      if (sizes[space] != 0) {
        AllocationResult allocation;
        if (space == NEW_SPACE) {
          allocation = new_space()->AllocateRaw(sizes[space]);
        } else {
          allocation = paged_space(space)->AllocateRaw(sizes[space]);
        }
        FreeListNode* node;
        if (!allocation.To(&node)) {
          if (space == NEW_SPACE) {
            Heap::CollectGarbage(NEW_SPACE,
                                 "failed to reserve space in the new space");
          } else {
            AbortIncrementalMarkingAndCollectGarbage(
                this, static_cast<AllocationSpace>(space),
                "failed to reserve space in paged space");
          }
          gc_performed = true;
          break;
        } else {
          // Mark with a free list node, in case we have a GC before
          // deserializing.
          node->set_size(this, sizes[space]);
          locations_out[space] = node->address();
        }
      }
    }
  }
  if (gc_performed) {
    // Failed to reserve the space after several attempts.
    V8::FatalProcessOutOfMemory("Heap::ReserveSpace");
  }
}

즉, AllocateRaw() 함수의 실행 결과에 대해 allocation.To(&node) 를 실행하여 이 값이 false 이면 Heap::CollectGarbage()를 호출. 하지만 정상 실행되는 경우 이 값이 true를 리턴하여 else 문으로 진입하는 것을 확인.

node:    file format elf64-x86-64
 
Disassembly of section .text:
 
00000000008df480 <v8::internal::Heap::ReserveSpace(Int *, unsigned char **)>:
...
  8df500:       e8 0b 8e fb ff          callq  898310 <v8::internal::PagedSpace::AllocateRaw(int)>
  8df505:       49 89 c5                mov    %rax,%r13
  8df508:       83 fa 08                cmp    $0x8,%edx
  8eca0b:       0f 85 8f 00 00 00       jne    8ecaa0 <v8::internal::Heap::ReserveSpace(int*, unsigned char**)+0x120>
  8eca11:       42 8b 14 bb             mov    (%rbx,%r15,4),%edx
  8eca15:       4c 89 e6                mov    %r12,%rsi
  8eca18:       4c 89 ef                mov    %r13,%rdi
  8eca1b:       e8 f0 e9 04 00          callq  93b410 <v8::internal::FreeListNode::set_size(v8::internal::Heap*, int)>
...
  8ecaa0:       45 85 f6                test   %r14d,%r14d
  8ecaa3:       75 1b                   jne    8ecac0 <v8::internal::Heap::ReserveSpace(int*, unsigned char**)+0x140>
  8ecaa5:       31 c9                   xor    %ecx,%ecx
  8ecaa7:       ba b0 0f cb 00          mov    $0xcb0fb0,%edx
  8ecaac:       31 f6                   xor    %esi,%esi
  8ecaae:       4c 89 e7                mov    %r12,%rdi
  8ecab1:       e8 7a fe ff ff          callq  8ec930 <v8::internal::Heap::CollectGarbage(v8::internal::AllocationSpace, char const*, v8::GCCallbackFlags) [clone .constprop.435]>
...

8df508 부분을 보면 call 이후 edx (rdx) 레지스터에 바로 접근하고 있는것을 확인할 수 있음. PagedSpace::AllocateRaw() 함수에서 이 값을 설정하고 리턴해 주는 듯 하나 mcount_return 과정에서 이 레지스터가 다른 용도로 사용되어 값이 사라짐. 이후 edx는 더이상 올바른 값(8)을 가지지 않기 때문에 8ecaa0 부분으로 점프하고 결국 Heap::CollectGarbage() 함수를 호출하게 됨.

x86 (64) calling convention을 보면 rdx 레지스터는 caller-saved register 이기 때문에 함수 호출 이후에 이 값을 사용하려면 스택에 저장/복원하는 과정이 필요함. 하지만 이 경우를 보면 그렇지 않은 경우가 있는 듯함. 커널의 ftrace return 코드 확인 결과 rdx를 저장/복원하는 코드가 포함되어 있음. - 확인 결과 일부 instruction (imul, idiv)의 경우 128비트 결과를 리턴하기 위해 rdx 를 사용하는 경우가 있음. 따라서 잠재적으로 rdx가 리턴값을 저장하는 용도로 사용될 가능성이 있으므로 이를 저장/복원하는 것이 맞음.

Garbage Collection

rdx 레지스터를 저장/복원하게 수정한 결과 해당 부분을 통과하여 실행되는 것을 확인. 하지만 마찬가지로 아래와 같이 garbage collection 부분에서 segfault 발생

$ ftrace node-pg hello.js
...
[21] v8::internal::InnerPointerToCodeCache::GetCacheEntry
[20] v8::internal::ExitFrame::Iterate
[19] v8::internal::Isolate::Iterate
[18] v8::internal::Isolate::Iterate
[17] v8::internal::Heap::Scavenge
[16] v8::internal::Heap::PerformGarbageCollection
[15] v8::internal::Heap::CollectGarbage
[14] v8::internal::Heap::CollectGarbage
[13] v8::internal::Factory::NewRawOneByteString
[12] v8::internal::Factory::NewStringFromOneByte(v8::internal::Vector
[11] v8::internal::Factory::NewStringFromUtf8(v8::internal::Vector
[10] v8::Local
[9] v8::String::NewFromUtf8
[8] node::DefineJavaScript(node::Environment*, v8::Handle
[7] node::Binding(v8::FunctionCallbackInfo
[6] v8::internal::FunctionCallbackArguments::Call(void (*)(v8::FunctionCallbackInfo
[5] v8::internal::Builtin_HandleApiCall
[4] v8::internal::Execution::Call(v8::internal::Isolate*, v8::internal::Handle
[3] v8::Function::Call(v8::Handle
[2] node::LoadEnvironment
[1] node::Start
[0] main

확인 결과 node.js 내부적으로 garbage collection을 위해 코드 영역을 검사하는데 이 때 stack frame 을 순회하며 JIT 컴파일된 코드인지 검사하는 듯 함. 이 과정에서 실행되는 코드는 항상 node.js (v8)에 의해 관리되는 영역에 속해 있다고 가정하는 듯 하며, 이를 위해 특정 메타데이터에 접근하는 과정에서 잘못된 주소로 인한 오류가 발생하는 것으로 판단됨. 이를 해결하기 위해서는 node.js 소스를 직접 수정하는 방법을 사용해야 할 듯 함. 이를 위해 libmcount 라이브러리 내에 mcount_restore/reset 함수를 추가하여 저장된 return address stack을 모두 복원하고 다시 덮어쓰는 기능을 타겟 프로세스 내에서 제어할 수 있도록 하였음.

$ diff -u node-v0.12.0/deps/v8/src/frames.cc{.orig,}
--- node-v0.12.0/deps/v8/src/frames.cc.orig       2015-08-05 11:37:13.529887583 +0900
+++ node-v0.12.0/deps/v8/src/frames.cc    2015-08-05 12:03:19.133264032 +0900
@@ -519,7 +519,14 @@
 }
 
 
+extern "C" {
+  extern __attribute__((weak)) void mcount_restore(void);
+  extern __attribute__((weak)) void mcount_reset(void);
+}
+
 void ExitFrame::Iterate(ObjectVisitor* v) const {
+  mcount_restore();
+
   // The arguments are traversed as part of the expression stack of
   // the calling frame.
   IteratePc(v, pc_address(), LookupCode());
@@ -527,6 +534,8 @@
   if (FLAG_enable_ool_constant_pool) {
     v->VisitPointer(&constant_pool_slot());
   }
+
+  mcount_reset();
 }

이제 node.js 빌드 시 libmcount가 함께 링크되도록 configure 파일을 수정해야 함. 하지만 이 때 mksnapshot 프로그램이 실행되는 과정에서 libmcount를 찾을 수 없어 오류 발생. 이를 해결하기 위해서는 out/deps/v8/tools/gyp/mksnapshot.target.mk 파일의 LIBS 부분에서 libmcount 제거해야 함.

결론

다음과 같은 두가지 수정 사항이 필요하였음.

1. mcount_return 실행 시 rdx 레지스터 값 저장/복원
2. 타겟 프로세스가 직접 stack frame을 접근하는 경우 원래 상태를 복원하기 위해 mcount_restore()를 호출하도록 수정. 하지만 다시 mcount 가 정상 실행되려면 동일한 함수 내에서 mcount_reset()를 호출해야 함.

이렇게 수정한 결과 최종적으로 -pg 옵션으로 빌드한 경우에도 node.js 가 정상 실행되며 "Hello world" 를 출력하는 것을 확인!! ㅜ.ㅜ