현재 학원에서 select 모델 기반 싱글스레드 MMO 서버를 개발하고 있다.
이 서버를 개발하는 과정에서 겪은 삽질 경험(?)을 기록하고, 더 나아가 덤프 파일을 분석해보려고 한다.
문제 상황
문제는 이렇다. 로컬에서는 문제없이 잘 작동하는데, 서버 컴퓨터에서 프로세스를 실행하면 얼마 못가 크래시가 발생했다. 웬만큼 문제가 예상되는 곳들에는 __debugbreak를 통한 assert를 걸고 있는데도 로그조차 남지 않고 그냥 죽어버렸다. 어디가 문제인지 찾기 위해서는 덤프를 남기고 덤프를 분석해야하는 상황이었다. SetUnhandledExceptionFilter를 통해 콜백을 등록해 덤프를 생성할 수 있다.
콜스택
일단 덤프 파일을 열어서 콜스택을 보자. 로그를 남기면서 시간을 얻어올 때 커널쪽에서 예외를 뱉었다. 정확하게는 std::chrono::get_tzdb_list()에서 발생한 오류였다.
그게 뭔데...
tzdb는 time zone db라는 의미로, 타임존 정보를 담고 있는 데이터베이스이다. 로그를 남길 때 시간 정보를 남기는데, 이 부분에서 오류가 나는 것이었다. 조금 더 자세하게는 current_zone()를 호출하다가 예외가 발생한 것. 로그를 남기다가 크래시가 발생하니 로그가 남을 턱이 없었다.
헛발질(?)
처음 추측한 것은 하드웨어 문제다. 서버에서 사용하는 CPU가 특정 명령어 확장을 지원하지 않는게 아닐까? 하는 의심이 든 것. CPU가 오래되어서든, 서버용 CPU라서든. 그러나 ntdll.dll의 어셈블리를 살펴봤을 때 특별한 확장 명령이 보이지도 않았고, 사용중인 Xeon E5-2680 v4는 생각보다 오래된 CPU도 아니었다(AVX2까지 지원한다).
일단 해결부터
과제의 데드라인이 꽤 촉박해서, 더 자세한 분석보다는 콜스택에 보이는 chrono::get_tzdb_list를 키워드로 구글링했다. 여기에서 금방 이유를 찾을 수 있었다. 타임존 정보는 세계 각지에서 법안이 통과됨에 따라 변경이 잦기 때문에, STL에 bake 해둘 수 없었고 운영체제에서 해당 내용을 지원해야하며 버전에 따라 제약이 있다고 한다. 1809 버전에서는 해당 기능을 지원하지 않는데, 서버에서 사용하는 운영체제는 Windows Server 2019로 1809버전인 Windows 10을 기반으로 하기 때문에 이를 지원하지 않아 예외가 발생한 것이다.
그래서 로그를 남기는 부분의 코드를 위와 같이 API를 기반으로 하여 수정했다. 이 버전으로 다시 실행하니 크래시 나는 문제는 발생하지 않았다.
...하지만 이렇게 끝나면 얻어가는 것이 부족할 것 같다. 그래서 일단 pdb 파일과 덤프 파일을 따로 백업 해두었고, 해당 변경사항도git에 커밋하여 언제든지 이 시점으로 돌아와 더 덤프를 분석할 수 있도록 남겨두었다.
지금은 기쁘게도 과제를 완성하고 통과 되었기에, 이 덤프 파일을 가져와서 더 자세하게 분석해보고 여러가지 경험과 지식을 쌓아보려고 한다.
분석의 시작
Windows via C/C++에서 배웠던 것 처럼, $err,hr을 통해 발생했던 에러가 무엇인지 살펴보았다. 매개변수가 틀리다고 나왔다. 뭔가 호출 과정에서 시스템콜이 있었고, 그게 실패했다는 것 외에 영양가 있는 정보는 아닌 것 같다.
기호 로드를 통해 확인해보면 RcCondolidateFrame()에서 타고 올라와서 예외 처리가 작동했다는 것은 알 수 있다. 하지만 여전히 원인을 알기는 어렵다. 제대로 콜스택이 보이지 않는데, 아마 ntdll.dll의 코드가 꼬리 호출 최적화(tail call optimization) 되어있는 등의 이유인 것 같다(가벼운 추측이다). 어쨌든 어디서, 어떤 흐름을 타고 RcCondolidateFrame로 오게 되었는지에 대한 정보를 찾을 수 없다.
그나마 그 다음에 코드를 볼 수 있는 구간에서 ExceptionCode라는걸 찾을 수 있었는데, 0xe06d7363이다. 이 코드 자체에 세분화된 정보가 있는건 아니고, C++에서 던진 예외라는걸 알려주는 것이라고 한다. 조금 더 자세히 알아보니, 이 정보를 통해 예외 객체의 이름을 찾는 방법이 있었다(여기에 소개되어있다).
PROCESS_NAME: Server.exe
ERROR_CODE: (NTSTATUS) 0xe06d7363 - <Unable to get error code text>
EXCEPTION_CODE_STR: e06d7363
EXCEPTION_PARAMETER1: 0000000019930520
EXCEPTION_PARAMETER2: 000000e82b6efe20
EXCEPTION_PARAMETER3: 00007ff682bb67f0
EXCEPTION_PARAMETER4: 7ff682780000
...
0:000> dd 00007ff682bb67f0 l4
00007ff6`82bb67f0 00000000 0012dde6 00000000 00436810
0:000> dd 7ff682780000+00436810 l2
00007ff6`82bb6810 00000004 00436360
0:000> dd 7ff682780000+00436360 l2
00007ff6`82bb6360 00000000 00438308
0:000> da 7ff682780000+00438308+10
00007ff6`82bb8318 ".?AVsystem_error@std@@"
0:000> dt Server!std::systemerror 000000e82b6efe20
이를 따라 WinDbg 상에서 추적해보니 이름을 찾을 수 있었다. 맹글링된 이름이지만 std::system_error 라는 것을 알 수 있다. 즉, OS에 관련된 에러가 발생한 것이다.
더 자세한 것을 살펴보자. 일단, 블로그 글에 따르면 EXCEPTION_PARAMETER2: 000000e82b6efe20는 예외 객체의 포인터다.
0:000> dc 000000e82b6efe20 La
000000e8`2b6efe20 82b2d790 00007ff6 20300ba0 0000022c ..........0 ,...
000000e8`2b6efe30 00000001 00000000 0000007e cccccccc ........~.......
000000e8`2b6efe40 82bb7038 00007ff6 8p......
일단 내가 사용 중인 비주얼 스튜디오 2022에서 구현된 STL 기준, std::system_error는 40바이트이므로 그 크기만큼 메모리를 쭉 펼쳐서 살펴보았다. 상속 구조를 봐가며, 이 메모리를 다음과 같이 파악할 수 있었다.
82b2d790 00007ff6 : vtable 주소
20300ba0 0000022c : 예외 메시지를 설명하는 what 주소
00000001 00000000 : 그 문자열을 Free 해야하는지를 저장하는 플래그 1바이트와 패딩
0000007e : 에러코드
cccccccc : 패딩(디버그 빌드라서 cc로 밀려있음)
82bb7038 00007ff6 : 에러 카테고리 주소
여기에서 가장 직접적인 힌트를 얻을 수 있는 what에 접근해보았다.
0:000> da 0000022c20300ba0
0000022c`20300ba0 "The specified module could not b"
0000022c`20300bc0 "e found."에러 메시지는 이렇다. "The specified module could not be found". 지정된 모듈을 찾을 수 없다는 것.
0:000> k
*** Stack trace for last set context - .thread/.cxr resets it
# Child-SP RetAddr Call Site
00 000000e8`2b6ed930 00007ff6`82a18e93 KERNELBASE!RaiseException+0x69
01 000000e8`2b6eda10 00007ff6`82a17a35 Server!__RethrowException+0x33 [D:\a\_work\1\s\src\vctools\crt\vcruntime\src\eh\frame.cpp @ 1380]
02 000000e8`2b6eda40 00007ff8`fad94726 Server!__FrameHandler4::CxxCallCatchBlock+0x275 [D:\a\_work\1\s\src\vctools\crt\vcruntime\src\eh\frame.cpp @ 1484]
03 000000e8`2b6edb10 00007ff6`82924b4a ntdll!RcConsolidateFrames+0x6
04 000000e8`2b6f0860 00007ff6`82924a91 Server!std::chrono::get_tzdb_list+0x9a [C:\Program Files\Microsoft Visual Studio\2022\Community\VC\Tools\MSVC\14.44.35207\include\chrono @ 2360]
05 000000e8`2b6f09e0 00007ff6`829204e1 Server!std::chrono::get_tzdb+0x21 [C:\Program Files\Microsoft Visual Studio\2022\Community\VC\Tools\MSVC\14.44.35207\include\chrono @ 2382]
06 000000e8`2b6f0ae0 00007ff6`8290b9e9 Server!std::chrono::current_zone+0x21 [C:\Program Files\Microsoft Visual Studio\2022\Community\VC\Tools\MSVC\14.44.35207\include\chrono @ 2390]
07 000000e8`2b6f0be0 00007ff6`82943f48 Server!Log+0x89 [C:\Server\DebugUtils.cpp @ 27]
08 000000e8`2b6f11b0 00007ff6`829437a2 Server!RecvMsg+0x128 [C:\Server\Network.cpp @ 355]
09 000000e8`2b6fe260 00007ff6`82933831 Server!ProcessNetwork+0x752 [C:\Server\Network.cpp @ 194]
0a 000000e8`2b6ff580 00007ff6`82a0b2e9 Server!main+0xc1 [C:\Server\main.cpp @ 57]
0b 000000e8`2b6ff740 00007ff6`82a0b1d2 Server!invoke_main+0x39 [D:\a\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl @ 79]
0c 000000e8`2b6ff790 00007ff6`82a0b08e Server!__scrt_common_main_seh+0x132 [D:\a\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl @ 288]
0d 000000e8`2b6ff800 00007ff6`82a0b37e Server!__scrt_common_main+0xe [D:\a\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_common.inl @ 331]
0e 000000e8`2b6ff830 00007ff8`f8307ac4 Server!mainCRTStartup+0xe [D:\a\_work\1\s\src\vctools\crt\vcstartup\src\startup\exe_main.cpp @ 17]
0f 000000e8`2b6ff860 00007ff8`fad4a8c1 kernel32!BaseThreadInitThunk+0x14
10 000000e8`2b6ff890 00000000`00000000 ntdll!RtlUserThreadStart+0x21자, 그럼 콜스택을 정리해보자면 로그를 찍다가 std::chrono::current_zone을 호출했고, 내부에서 get_tzdb_list를 호출해서 타임존 정보를 불러오다가 "지정된 모듈을 찾을 수 없다"는 예외와 함께 크래시가 발생했다. 이 정도 분석이면 get_tzdb_list라는 키워드로 추가적인 조사를 통해 방금 내가 찾았던 MS 블로그의 내용을 확인한 다음, 내 서버에서 발생한 문제가 동일한 문제임을 알 수 있을 것이다.