저는 콘솔 디버거입니다 (역주1: 원 제목의 ‘puts debuggerer’를 의역하였습니다. 루비의 puts는 전달받은 인자를 표준 출력(stdout)해주는 메서드입니다. 이후에도 puts debugging은 모두 콘솔 디버깅으로 번역하겠습니다). 진짜 디버거( pry , byebug 등)를 사용하는 사람들을 폄하하고자 이 이야기를 하는게 아닙니다. 진짜 디버거는 아주 좋다고 생각하지만, 저는 하나라도 제대로 배울 시간을 들이지 못했습니다. 매번 한 개라도 써보려고 하다가 결국엔 한동안 사용하지 않고, 다시 사용방법을 배워야만 합니다. 어쨌든, 이번 기회에 여러분에게 콘솔 디버깅을 할 때 사용하는 트릭을 좀 알려드리고자 합니다. 저는 이 트릭들을 무언가가 어떻게 작동하는지 이해가 되지 않을때나 작동 원리를 더 알고싶을 때 사용합니다. 아래에 이야기하게 될 대부분의 것들은 절대로 최선의 방법(best practice)가 아니며 여러분들은 디버깅 세션이 끝나면 절대 이 코드들을 남겨두어선 안됩니다. 그러나 여러분이 무엇을 디버깅하던지 아주 유용하다고 생각합니다. 정말로 뭐든지요. 전역 변수, 메서드 재정의, 조건문 추가, 불러오기 경로 수정, 몽키 패칭, 콜 스택 출력 등 뭐든지요.
저는 이 포스트에서 최대한 실제 접하는 예시들을 보여드리고 싶었습니다. 하지만 대부분의 예시들은 제가 레일즈의 보안 이슈를 디버깅하려고 할 때 나온 것들이라서, 이 코드의 테크닉은 재활용하셔도 좋지만 코드 전체를 그대로 쓰시면 안됩니다. 제가 디버깅하려는 코드들은 정상적으로 동작하지 않습니다. 거기다 이 코드를 사용하시는걸 원치도 않습니다.
매 섹션에 제가 겪었던 문제들을 제목으로 적어두었으며, 내용 부분에 제가 사용한 해결책을 적어두었습니다.
어디에 문제가 있는진 알겠는데, 어떻게 거기까지 가야할지 모르겠다
가끔 저는 문제가 어딨는지는 알지만 어떻게 그 부분까지 가는지 모르는 이슈들을 디버깅할 때가 있습니다. 이럴 때마다 저는 puts caller 를 넣어서 콜 스택을 끄집어냅니다.
예를 들어 제가 이런 코드를 작성했다고 칩시다.
여기서 저는 기본 블록이 어떻게 호출되는지 알고 싶을 때 이렇게 합니다.
위의 코드는 90개의 해시 태그를 출력하고 콜 스택을 출력한 뒤에, 나머지 90개의 해시 태그를 출력할 겁니다. 해시 태그는 여러번 호출될 때를 대비해서 콜 스택을 쉽게 구분하기 위해 넣어두었습니다. 참고로 이걸 “해시 태그”라고 부르는건 여러분을 골려주려고 그러는 겁니다.
저는 이 방법을 꽤 자주 사용하기 때문에 Vim 단축키를 지정해두었습니다.
이렇게 하면 <leader>wtf 키 조합으로 커서가 있는 위치 바로 밑에 디버깅 코드를 삽입합니다.
콜 스택을 한 번만 출력하고 싶어
그냥 콜 스택을 출력한 뒤에 exit! 를 사용하거나, raise 를 호출하세요. raise 는 예외를 출력할거고, 어쨌든 콜 스택을 볼 수 있을겁니다.
콜 스택을 특정 경우에만 보고 싶어
이건 그냥 디버깅 코드니까 여러분이 하고싶은대로 하시면 됩니다. 예를 들어 제가 해시에 무언가를 추가할 때마다 콜 스택을 호출하고 싶다고 한다면, 이렇게 하면 됩니다.
어차피 전 이 코드를 없애버릴거니까 어떤 이상한 조건문도 마음대로 추가할 수 있지요!
메서드를 호출했는데, 이게 어디에 있는건지 모르겠다
메서드를 호출했는데 그 메서드가 어디에 구현되어있는지 모를 때, 저는 source_location 메서드와 함께 method 메서드를 사용합니다. 예를 들어 (레일즈) 컨트롤러 안에 있는 액션이 render 메서드를 호출하고 있을 때, 저는 그 메서드를 어디서 호출하는지 알고 싶었습니다.
가끔 당장 사용하고 있는 메서드가 실제로는 문제의 본질이 아닐 수 있습니다. 그래서 method 메서드를 사용하는 트릭은 별 도움이 안될 겁니다. 이럴 때엔 저는 TracePoint 라고 하는 더 큰 추적기(a larger hammer)를 사용합니다. render 메서드로부터 호출 된 모든 메서드의 리스트를 추출하기 위해 다시 한번 예를 들어보겠습니다. 리스트에 보이는 메서드들은 render 메서드가 직접 호출한 것은 아니지만 어딘가로부터 호출 된 것입니다.
저기 위치한 TracePoint 는 모든 “호출(:call)” 이벤트마다 작동하고, 블록은 메서드 이름과 호출된 위치를 출력할 것입니다. 여기서 “호출” 이라 함은 루비 메서드가 호출되는 경우를 말합니다(C 메서드는 제외). 만약 C 메서드가 호출되는 것을 보고 싶으시다면 :c_call 을 사용하세요. 이 예시는 엄청난 양의 결과가 출력될겁니다. 저는 호출될 메서드가 꽤 적거나, 도대체 어디부터 찾아봐야 할지 모를 때 이 방법을 사용합니다.
예외가 일어나는 것은 알겠지만, 어디서 발생하는지 모르겠다
예외가 발생할 때 실제로 어디서 예외가 발생했는지 모를 때가 있습니다. 이 예시는 레일즈 3.0.0을 기준으로 작성되었지만(참고로 이 문제는 수정되었습니다), 일단 이런 코드가 있다고 해보죠.
SQL은 작동하지 않을 테고, 예외가 일어날 겁니다. 그렇다면 예외가 어떻게 발생하는지 보겠습니다.
여러분이 추적 내역(backtrace) 을 읽어보셨다면 (역주2: backtrace하면 역추적 이라는 말이 직역하기는 좋지만, 보통 루비에서 backtrace를 떠올릴 때 콘솔에 뜨는 십수 줄의 추적 내역이 연상될 때가 많아서 추적 내역으로 번역하였습니다), 예외가 abstract_adapter.rb의 202번째 줄에서 발생했다는 것을 알 수 있습니다. 그러나 이 코드는 예외가 발생한 상황에서 다시 예외를 일으키도록 되어있는게 보일 겁니다. 그렇다면 실제로는 어디서 예외가 일어난 걸까요? 정답을 찾기 위해 puts 를 사용하거나 루비의 -d 플래그를 사용할 수 있습니다.
-d 플래그는 경고를 활성화하고 모든 예외 발생을 출력합니다. 네, 실제로는 엄청나게 많은 양의 결과물이 출력되겠지요. 그러나 끝부분을 살펴보시면 이렇게 되어있습니다.
실제 예외는 여기서 발생했습니다.
그리고 여기서 다시 예외가 일어났지요.
예외가 발생할 때 래핑된 뒤 다시 예외가 발생하는 경우에는 반드시 본래의 추적 내역을 노출해야 합니다. 그러므로 이 경우는 명백히 버그지만, 실제로 버그는 고쳐졌으며, 우리는 언젠가 또 이런 경우가 발생했을 때 해결하는 법을 알게 되었습니다.
커맨드 라인 도구를 -d 플래그와 함께 사용하여 실행
위의 기술을 RSpec 테스트에 적용하고 싶으시다면 이렇게 하시면 됩니다.
-d 플래그는 사용하고 싶은데 프로세스를 실행하는 방법을 모르겠다
Rake 테스트 작업은 기본적으로 서브 프로세스 안에서 당신의 테스트를 실행합니다. 말인 즉슨 ruby -d -S rake 같은 커맨드를 입력해도 서브 프로세스 안에 있는 여러분의 테스트에는 플래그가 적용되지 않는다는 뜻입니다. 이 경우 저는 RUBYOPT 환경 변수를 사용합니다.
RUBYOPT 환경 변수는 쉘에서 실행된 모든 루비 프로그램에 적용되고, 심지어 rake로부터 호출 된 서브 쉘에도 적용됩니다. 이를 응용하면 rspec 커맨드를 이렇게 다시 써볼 수 있습니다.
이 객체는 어디에서 온 걸까?
보통은 콜 스택을 출력하여 객체가 어디에서 왔는지 찾습니다. 하지만 가끔 객체가 콜 스택 바깥에 위치한 경우도 있습니다. 이럴 때는 객체가 어디에서 호출된 건지 찾기 힘듭니다.
이전에 “어디에 문제가 있는진 알겠는데, 어떻게 거기까지 가야할지 모르겠다” 파트에서 caller 를 사용하는 방법, “wtf 트릭” *(역주3: 글쓴이는 해당 방법을 소개할 때 Vim 단축키를 <leader>wtf 으로 설정하였습니다. 그래서 이를 “wtf trick”으로 명명한 것으로 보입니다)*을 보여드렸습니다. 여기서 저는 x 라는 값이 어떻게 할당되었는지 신경쓰였는데요, foo 메서드를 따라가다보면 baz 메서드에서 값을 가져오는 것을 볼 수 있습니다. 거대한 코드 베이스에서는 형제 트리에서 모든 호출과 로직을 따라가는게 아주 어렵습니다(코드를 자료구조의 그래프라고 생각한다면, foo 메서드는 두 개의 자손이 있는 겁니다. baz 와 bar 이죠. 그래서 baz가 bar 의 형제라고 여길 수 있습니다). 저는 게으르기 때문에 객체가 어디서 왔는지 찾기 위해 모든 메서드를 뒤지고 싶지 않았습니다. 그래서 저는 루비의 객체 할당 추적기(object allocation tracer)를 사용하는걸 좋아합니다. 루비의 할당 추적기는 루비 2.1버전부터 사용할 수 있습니다(확실한 것은 아닙니다). 제가 이 방법을 사용할 때는 가능한 빨리 require 한 뒤에 활성화합니다. 그러면 제가 찾고자 하는 할당 위치를 찾을 수 있지요.
프로그램을 실행하면 이런 결과를 얻습니다.
x 객체가 해당 파일의 14번째 줄에 있다는 것을 알게 되었습니다. 그러면 해당 라인으로 가서 “wtf 트릭” 을 반복하거나 프로그램에 무슨 문제가 있는지 발견할 때 까지 이 방법을 반복합니다.
저는 보통 객체 추적을 가능한 빠르게 시작합니다. 제 객체가 어디에 할당되었는지 모르니까요. 이런 추적은 프로그램의 속도를 떨어뜨리지만, 디버깅 중에는 신경쓸 필요가 없습니다.
나는 require 를 진짜 진짜 빨리 하고 싶어
바로 위에 보여드린 기술은 오로지 객체가 trace_object_allocations_start 메서드가 호출되고 난 뒤에 할당된 이후의 정보만 제공합니다. 파일이 require 되는 순간에 객체가 할당되어서, 도대체 무슨 파일이고 어디에 있는지 모를 때가 있습니다. 그래서 프레임워크 안에 있는 어떤 파일이라도 로드되기 전에 코드를 좀 실행시킬 필요가 있습니다. 이럴 때 저는 -r 플래그를 사용한 뒤 스크립트를 작성합니다.
우리가 User::BLACKLISTED_CLASS_METHODS 의 할당 위치를 찾는 코드를 작성했다고 칩시다.
그런데 우리는 이 어떤 파일이 이 상수를 할당했는지 모르고, 찾는 방법을 떠올리고 싶지도 않을 때가 있습니다(네, 이건 좀 억지로 꾸며낸 경우입니다). 이럴 때 y.rb 라는 파일을 작성해 보겠습니다.
그리고 저는 루비의 커맨드 라인 인자를 넣어서 이 파일을 실행할 때 바로 require 하도록 만들었습니다.
인자들을 찬찬히 살펴보면 -I. 는 “. 를 불러오기 경로로 추가하고”, -ry 는 require 'y' 와 같으며, 이후에 x.rb 를 실행하는 겁니다. 그러니 . 가 불러오기 경로로 추가되었고, x.rb 가 실행되기도 전에 y.rb 파일이 require 되었습니다. 그 결과로 BLACKLISTED_CLASS_METHODS 가 attribute_methods.rb 의 35번째 줄에 에 할당되어 있다는 사실을 알 수 있습니다. 만약 서브 프로세스 안에서 실행되는 코드에 이 기술을 적용하고자 한다면 RUBYOPT 를 함께 쓰면 됩니다.
객체가 어딘가에서 수정되었는데(mutated), 그 위치를 모르겠다
객체를 살펴보다 보면 이게 수정되고 있다는건 알겠는데, 어디서 수정되고 있는 지 모를 때가 있습니다. 이 때는 객체에 freeze 를 호출한 뒤에, 테스트를 실행해보고, 어디서 예외가 발생하는지 살펴보면 됩니다. 그 예로, 제가 어디에서 특정 변수가 수정되는지 알고 싶을 때가 있습니다. 코드를 살펴보니 이 변수가 수정된다는 것은 알고 있었지만, 어디서부터 수정이 일어나는지 알지 못했습니다. 그래서 코드를 이렇게 수정해봤습니다.
그리고 나서 레일즈 서버를 실행하면 예외가 발생하며 추적 내역이 보여집니다.
이제 처음에 수정이 발생한 곳을 발견했습니다. 만약 이 부분이 여러분이 찾고자 하는 부분이 아니라면 작성해둔 freeze 를 삭제한 뒤에 내역을 따라가서 수정된 부분 이후에 다시 덧붙이면 됩니다.
교착 상태(deadlock)에 빠졌는데, 어디서 문제가 생겼는지 모르겠다
저에게 스레드와 관련된 이슈가 발생했고, 문제를 어디에서 해결해야할 지 몰랐을 때, 저는 살아있는 스레드를 검사해보기 위해 코드를 좀 추가했습니다. 예를 들어 저는 이 이슈를 디버깅하고 있었습니다. 애플리케이션 서버가 막혀있는데, 대체 어디서 문제가 발생했는지 몰랐습니다. 그래서 어디서 스레드가 막혀있는지 찾기 위해 x.rb 라는 파일을 작성했습니다.
그리고 앱 서버를 이렇게 실행했습니다.
이제 앱 서버가 막혔을 때, 컨트롤+T 키를 누르면(죄송하지만 OS X에서만 작동합니다, 리눅스에서는 kill 을 사용해야 합니다), 모든 스레드의 추적 내역을 볼 수 있습니다.
가독성을 위해 결과물을 조금 잘라냈습니다만, 여러분은 이제 각각의 스레드가 무엇을 하는지 볼 수 있습니다. 그리고 어느 스레드 두 개가 교착 상태에 빠졌는지 쉽게 발견할 수 있습니다(정답은 마지막 두 개입니다).
특정한 시간에만 언제 메서드가 실행되는지 알고 싶다
일정 시간 뒤에 메서드가 언제 실행되었는지 알고 싶을 때가 있습니다. 저는 애플리케이션이 구동된 뒤에start_exclusive 메서드가 언제 호출되는지 알고 싶었습니다. 이럴 때 위에 보여드린 trap 트릭과 전역 변수를 조합하여 해결했습니다.
먼저 start_exclusive 를 이렇게 수정했습니다.
그리고 x.rb 라는 파일을 작성했습니다.
그리고 앱 서버를 구동하고 모든 요소가 준비되면 컨트롤+T를 눌러서 제 전역 변수를 true 로 바꿉니다. 그리고 로그 메세지들을 살펴볼 수 있게 됩니다.
간만에 엄청나게 긴 양의 글을 번역했습니다. 그래도 맘 잡고 하니 생각보다 오래 걸리지도 않고, 초벌번역의 퀄리티도 조금씩 올라가고 있다고 느끼고 있습니다.
이번에 소개해 드린 글은 콘솔에 디버깅 하는 방법을 소개하는 글입니다. 보통은 디버깅 툴로 byebug, pry-byebug 등을 사용하실 겁니다. 저도 어지간한 디버깅을 그렇게 처리하고 있지만.. 본문의 내용처럼 좀 깊은 부분을 들여다볼 때는 일일히 깊숙하게 파고들기 힘들 때가 많습니다. 좀 더 자신이 사용하고 있는 코드의 깊은 부분을 들여보고자 할 때 아주 유용한 테크닉이 될 것이라 생각합니다.
번역된 챕터 제목들의 말투가 조금 이상하다고 느끼실텐데, 들어가는 글에서 원 저자가 ‘어차피 블로그 포스트니까 신경 안쓰고 말투를 편하게 한다’는 식으로 쓰여있길래 그 느낌을 가능한 한 살려서 작성해보았습니다.
글을 읽다 보면 레일즈같은 거대한 오픈 소스에 기여하는 분들은 ‘어떻게 이 방대한 코드를 다 고려하면서 개발을 하는걸까?’ 하는 생각에 더욱 존경심이 들더군요. 레일즈 뿐 아니라 다른 오픈소스 프레임웍들도 마찬가지입니다. 언젠가는 오픈소스에 기여했다는 족적을 꼭 남겨 보고 싶습니다.
현재 Hanami 기반으로 개발을 하고 있다보니 문서화가 덜 되어 ‘소스를 까볼’ 일이 많은데 이런 기술을 더 유용하게 사용해볼 수 있겠습니다. 이 글을 보는 다른 분들은 어떻게 ‘프로그램의 소스를 살펴 보시는지’ 궁금하기도 하고, 더 유용한 디버깅 팁이 있는지도 궁금해집니다.