Microsoft MVP성태의 닷넷 이야기
글쓴 사람
정성태 (techsharer at outlook.com)
홈페이지
첨부 파일

windbg 분석 사례 - 종료자(Finalizer)에서 예외가 발생한 경우 비정상 종료(Crash) 발생

이번엔 일본의 고객사에서 발생한 문제입니다. 웹 애플리케이션이 알 수 없는 이유로 비정상 종료를 한다고 하는데 원인을 모르겠다고 하면서 혹시나 제니퍼 닷넷을 설치하면 알 수 있을까 싶어 설치를 했다고 합니다. 물론! 그 어떤 APM 제품도 "비정상 종료"를 하는 경우에는 그 원인을 잡아낼 수 없습니다. ^^

이런 경우, 이미 구매한 고객사에서 문의를 한 것이기 때문에 메모리 덤프를 보내주면 원인을 찾아서 알려드린다고... 일종의 서비스를 제공했습니다. 며칠 후 고객사 측에서 메모리 덤프를 보내줬는데, 이게 좀 문제가 있습니다. Full Memory 덤프를 보내준 것이 아니고 윈도우에서 제공하는 crash 덤프를 보내준 것입니다. 이런 유의 덤프는 windbg에서 로드할 때 다음과 같은 메시지를 볼 수 있습니다.

Microsoft (R) Windows Debugger Version 10.0.18239.1000 X86
Copyright (c) Microsoft Corporation. All rights reserved.


Loading Dump File [C:\temp\AppCrash_w3wp.exe_9ea2bfa22...d02dcbd9\WER4731.tmp.hdmp]
User Mini Dump File: Only registers, stack and portions of memory are available

그래도 약 500MB가 넘는 덤프라서 어느 정도의 정보는 담고 있기 때문에 "!analyze -v" 명령을 이용해 분석을 해봤습니다.

0:015> !analyze -v
...[생략]...

DUMP_CLASS: 2

DUMP_QUALIFIER: 400

CONTEXT:  (.ecxr)
eax=1a5af368 ebx=00000005 ecx=00000005 edx=00000000 esi=1a5af414 edi=01158b10
eip=772bc42d esp=1a5af368 ebp=1a5af3b8 iopl=0         nv up ei pl nz ac po nc
cs=0023  ss=002b  ds=002b  es=002b  fs=0053  gs=002b             efl=00000212
KERNELBASE!RaiseException+0x58:
772bc42d c9              leave
Resetting default scope

FAULTING_IP: 
KERNELBASE!RaiseException+58
772bc42d c9              leave

EXCEPTION_RECORD:  (.exr -1)
ExceptionAddress: 772bc42d (KERNELBASE!RaiseException+0x00000058)
   ExceptionCode: e0434352 (CLR exception)
  ExceptionFlags: 00000001
NumberParameters: 5
   Parameter[0]: 80131622
   Parameter[1]: 00000000
   Parameter[2]: 00000000
   Parameter[3]: 00000000
   Parameter[4]: 739d0000

DEFAULT_BUCKET_ID:  CLR_EXCEPTION_NOSOS

PROCESS_NAME:  w3wp.exe

EXCEPTION_CODE: (HRESULT) 0x80131622 (2148734498) - <Unable to get error code text>

...[생략]...

다른 오류는 없고 위와 같이 CLR Exception 하나가 발생한 후 KERNELBASE!RaiseException이 발생했습니다. 그런데 이게 비정상 종료를 이끌었는지는 확신할 수 없습니다. 그래서 고객사 측에 이 시점의 이벤트 로그를 보내달라고 요청했고 다음은 이에 대한 내용입니다.

Log Name:      Application
Source:        ASP.NET 4.0.30319.0
Date:          2018-09-19 오후 1:37:51
Event ID:      1325
Task Category: None
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      testsrv.co.jp
Description:
ハンドルされていない例外が?生し、?理が中止されました。

Application ID: /LM/W3SVC/1/ROOT/MAPS

Process ID: 6084

Exception: System.ObjectDisposedException

Message: 閉じているファイルにはアクセスできません。

StackTrace:    at System.IO.__Error.FileNotOpen()
   at System.IO.FileStream.Flush(Boolean flushToDisk)
   at System.IO.FileStream.Flush()
   at System.IO.StreamWriter.Flush(Boolean flushStream, Boolean flushEncoder)
   at System.IO.StreamWriter.Dispose(Boolean disposing)
   at System.IO.StreamWriter.Close()
   at FileUtil.Close()
   at FileUtil.Finalize()

보는 바와 같이 System.ObjectDisposedException가 발생했고 연이은 로그에서,

Log Name:      Application
Source:        Application Error
Date:          2018-09-19 오후 1:37:53
Event ID:      1000
Task Category: Application Crashing Events
Level:         Error
Keywords:      Classic
User:          N/A
Computer:      testsrv.co.jp
Description:
Faulting application name: w3wp.exe, version: 7.5.7601.17514, time stamp: 0x4ce7a5f8
Faulting module name: KERNELBASE.dll, version: 6.1.7601.18798, time stamp: 0x5507b485
Exception code: 0xe0434352
Fault offset: 0x0000c42d
Faulting process id: 0x17c4
Faulting application start time: 0x01d44fb48944bb3a
Faulting application path: C:\Windows\SysWOW64\inetsrv\w3wp.exe
Faulting module path: C:\Windows\syswow64\KERNELBASE.dll
Report Id: c50f0479-bbc5-11e8-9b1a-0050568f06bc
Faulting package full name: %14
Faulting package-relative application ID: %15

비정상 종료가 발생했음을 알려주고 있습니다. 따라서 비정상 종료를 이끈 것이 ObjectDisposedException 예외의 발생으로 인한 것임을 짐작할 수 있습니다.




그런데 ObjectDisposedException 예외가 발생했다고 해서 왜? 비정상 종료되는 것일까요? 이유는 이벤트 로그에 찍힌 호출 스택을 통해 알 수 있습니다.

StackTrace:    at System.IO.__Error.FileNotOpen()
   at System.IO.FileStream.Flush(Boolean flushToDisk)
   at System.IO.FileStream.Flush()
   at System.IO.StreamWriter.Flush(Boolean flushStream, Boolean flushEncoder)
   at System.IO.StreamWriter.Dispose(Boolean disposing)
   at System.IO.StreamWriter.Close()
   at FileUtil.Close()
   at FileUtil.Finalize()

그렇습니다. 종료자에서 예외가 발생했고 그 종료자는 CLR에서 특별 관리하는 Finalizer 스레드이기 때문입니다. 실제로 간단한 웹 애플리케이션을 만들어 다음과 같이 재현해 볼 수 있습니다.

// Default.aspx
using System;

namespace WebApplication1
{
    public partial class Default : System.Web.UI.Page
    {
        protected void Page_Load(object sender, EventArgs e)
        {
            new ExUtil();
            new ExUtil();
            new ExUtil();
            new ExUtil();
            new ExUtil();
        }
    }

    public class ExUtil
    {
        ~FileUtil()
        {
            throw new ApplicationException("TEST");
        }
    }
}

// doGC.aspx
using System;

namespace WebApplication1
{
    public partial class Default : System.Web.UI.Page
    {
        protected void Page_Load(object sender, EventArgs e)
        {
            GC.Collect(2, GCCollectionMode.Forced);
            GC.Collect(2, GCCollectionMode.Forced);
        }
    }
}

위와 같이 2개의 페이지를 만들고 Default.aspx를 방문한 후, doGC.aspx를 방문하면 웹 애플리케이션이 비정상 종료합니다.




그런데, 고객사의 경우에는 한 가지 더 재미있는 점이 있습니다. 사실 StreamWriter는 Close 시에 내부 stream을 닫고 null 처리를 합니다. 그래서 두 번째 Close를 호출했을 때는 내부 Stream의 Close가 불리지 않으므로 ObjectDisposedException 예외가 발생하지 않습니다. 실제로 다음과 같은 소스 코드로 이를 확인할 수 있습니다.

using System;
using System.IO;

namespace WebApplication1
{
    public partial class Default : System.Web.UI.Page
    {
        protected void Page_Load(object sender, EventArgs e)
        {
            FileStream fs = new FileStream("c:\\temp\\test.txt", FileMode.OpenOrCreate, FileAccess.ReadWrite, FileShare.ReadWrite);
            StreamWriter sw = new StreamWriter(fs);

            new FileUtil(sw);
            new FileUtil(sw);
            new FileUtil(sw);
            new FileUtil(sw);
            new FileUtil(sw);
        }
    }

    public class FileUtil
    {
        static int _instance = 0;
        public int _id = 0;

        StreamWriter _sw;
        public FileUtil(StreamWriter sw)
        {
            _sw = sw;
            _instance++;

            _id = _instance;
        }

        ~FileUtil()
        {
            System.Diagnostics.Trace.WriteLine("~FileUtil: " + _id);
            _sw.Close();
        }
    }
}

위의 페이지 호출 후 doGC.aspx를 방문하면 FileUtil의 finalizer가 5번 호출되지만 프로세스는 여전히 잘 살아 있습니다. 왜냐하면 ObjectDisposedException이 발생하지 않기 때문입니다. 그렇다면 어떻게 고객사의 웹 애플리케이션에서는 예외가 발생한 것일까요? 가능성을 생각해 본다면 멀티 스레드로 인한 동시 Close 경우를 들 수 있습니다. 그런데 여기서 또 문제가 있는데 종료자를 호출하는 Finalizer 스레드는 프로세스마다 하나씩 배정되므로 다중 스레드 문제일 수는 없습니다.

따라서, 굳이 남은 한 가지 가능성을 고려한다면 ASP.NET 요청 스레드에서 Close를 하는 것과 동시에 Finalizer에서 동일한 StreamWriter 인스턴스의 Close를 호출하는 것을 생각할 수 있습니다. 과연 그럴 확률이 얼마나 될지? 응용 프로그램이 사용한 코드 유형에 따라 달라지겠지만 어쨌든 외부에서의 분석 결과는 그렇게 나옵니다.




이 문제를 해결하려면 어떻게 해야 할까요? 아쉽게도 이것은 2차 스레드에서 발생하는 예외로 인한 종료 현상과는 다릅니다.

비동기 코드 실행 중 예외로 인한 ASP.NET 프로세스 비정상 종료 현상
; https://www.sysnet.pe.kr/2/0/11383

ASP.NET 응용 프로그램이 예외로 프로세스가 종료된다면?
; https://www.sysnet.pe.kr/2/0/10863

따라서 aspnet.config 파일의 legacyUnhandledExceptionPolicy 옵션 설정과는 무관합니다.

<legacyUnhandledExceptionPolicy enabled="true" />

남은 방법은, 간단합니다. 그냥 종료자에서 예외가 발생하지 않도록 try/catch로 감싸는 것입니다.

public class FileUtil
{
    // ...[생략]...
    ~FileUtil()
    {
        try
        {
            // ...[생략]... throw new ApplicationException();
        } catch { }
    }
}

그러니까, 절대로 Finalizer 내에서는 예외를 발생시켜서는 안 됩니다.

(첨부 파일은 이 글의 예제 코드를 포함합니다.)




참고로, 해당 고객사에서는 FileUtil.Finalize에서 StreamWriter.Close를 굳이 호출할 필요는 없었습니다. 왜냐하면 Managed 자원은 Finalize에서 처리하지 않아도 참조가 없어지면 GC가 되기 때문입니다. 즉, Native 자원을 처리하는 것이 아니므로 굳이 구현할 필요가 없었던 Finalize로 인해 웹 응용 프로그램이 장애가 발생한 것입니다.

그나저나, 엄밀히 따지면 이 글은 windbg 분석 글은 아닙니다. ^^ 단지 굳이 어렵게 windbg 분석 없이도 이벤트 로그 만으로 해결할 수 있는 문제도 많다는 것을 말하고 싶었습니다. 게다가 일본의 그 고객사도 조금만 여유를 가지고 이벤트 로그의 내용을 자세히 봤다면 그 원인을 어렵지 않게 찾고, 또한 고칠 수 있었을 것입니다.




[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]

[연관 글]





[최초 등록일: ]
[최종 수정일: 10/10/2018 ]

Creative Commons License
이 저작물은 크리에이티브 커먼즈 코리아 저작자표시-비영리-변경금지 2.0 대한민국 라이센스에 따라 이용하실 수 있습니다.
by SeongTae Jeong, mailto:techsharer@outlook.com

비밀번호

댓글 쓴 사람
 




... [16]  17  18  19  20  21  22  23  24  25  26  27  28  29  30  ...
NoWriterDateCnt.TitleFile(s)
12002정성태8/12/20191630.NET Framework: 853. Excel Sheet를 WinForm에서 사용하는 방법 - 두 번째 이야기 [5]
12001정성태8/10/20192290.NET Framework: 852. WPF/WinForm에서 UWP의 기능을 이용해 Bluetooth 기기와 Pairing하는 방법
12000정성태8/9/20191717.NET Framework: 851. WinForm/WPF에서 Console 창을 띄워 출력하는 방법파일 다운로드1
11999정성태8/1/20191135오류 유형: 563. C# - .NET Core 2.0 이하의 Unix Domain Socket 사용 시 System.IndexOutOfRangeException 오류
11998정성태7/30/20191422오류 유형: 562. .NET Remoting에서 서비스 호출 시 SYN_SENT로 남는 현상파일 다운로드1
11997정성태7/30/20191980.NET Framework: 850. C# - Excel(을 비롯해 Office 제품군) COM 객체를 제어 후 Excel.exe 프로세스가 남아 있는 문제파일 다운로드1
11996정성태7/25/20192051.NET Framework: 849. C# - Socket의 TIME_WAIT 상태를 없애는 방법파일 다운로드1
11995정성태7/23/20191754.NET Framework: 848. C# - smtp.daum.net 서비스(Implicit SSL)를 이용해 메일 보내는 방법
11994정성태10/22/20192044개발 환경 구성: 454. Azure 가상 머신(VM)에서 SMTP 메일 전송하는 방법파일 다운로드1
11993정성태7/22/20191257오류 유형: 561. Dism.exe 수행 시 "Error: 2 - The system cannot find the file specified." 오류 발생
11992정성태7/22/20191332오류 유형: 560. 서비스 관리자 실행 시 "Windows was unable to open service control manager database on [...]. Error 5: Access is denied." 오류 발생
11991정성태7/18/2019900디버깅 기술: 128. windbg - x64 환경에서 닷넷 예외가 발생한 경우 인자를 확인할 수 없었던 사례
11990정성태3/16/20201853오류 유형: 559. Settings / Update & Security 화면 진입 시 프로그램 종료
11989정성태7/18/20191007Windows: 162. Windows Server 2019 빌드 17763부터 Alt + F4 입력시 곧바로 로그아웃하는 현상
11988정성태7/18/20191713개발 환경 구성: 453. 마이크로소프트가 지정한 모든 Root 인증서를 설치하는 방법
11987정성태7/17/20195056오류 유형: 558. 윈도우 - KMODE_EXCEPTION_NOT_HANDLED 블루스크린(BSOD) 문제
11986정성태7/18/20191080오류 유형: 557. 드라이브 문자를 할당하지 않은 파티션을 탐색기에서 드라이브 문자와 함께 보여주는 문제
11985정성태7/17/20191054개발 환경 구성: 452. msbuild - csproj에 환경 변수 조건 사용
11984정성태7/9/20192034개발 환경 구성: 451. Microsoft Edge (Chromium)을 대상으로 한 Selenium WebDriver 사용법
11983정성태7/8/20191136오류 유형: 556. nodemon - 'mocha' is not recognized as an internal or external command, operable program or batch file.
11982정성태7/8/20191104오류 유형: 555. Visual Studio 빌드 오류 - result: unexpected exception occured (-1002 - 0xfffffc16)
11981정성태7/7/20191433Math: 64. C# - 3층 구조의 신경망(분류)파일 다운로드1
11980정성태7/7/20196082개발 환경 구성: 450. Visual Studio Code의 Java 확장을 이용한 간단한 프로젝트 구축파일 다운로드1
11979정성태7/8/20191671개발 환경 구성: 449. TFS에서 gitlab/github등의 git 서버로 마이그레이션하는 방법
11978정성태7/6/20191431Windows: 161. 계정 정보가 동일하지 않은 PC 간의 인증을 수행하는 방법 [1]
11977정성태7/6/20192622오류 유형: 554. git push - error: RPC failed; HTTP 413 curl 22 The requested URL returned error: 413 Request Entity Too Large
... [16]  17  18  19  20  21  22  23  24  25  26  27  28  29  30  ...