성태의 닷넷 이야기
홈 주인
모아 놓은 자료
프로그래밍
질문/답변
사용자 관리
사용자
메뉴
아티클
외부 아티클
유용한 코드
온라인 기능
MathJax 입력기
최근 덧글
[정성태] Detecting blocking calls using asyn...
[정성태] 아쉽게도, 커뮤니티는 아니고 개인 블로그입니다. ^^
[정성태] 질문이 잘 이해가 안 됩니다. 우선, 해당 소스코드에서 ILis...
[양승조
] var대신 dinamic으로 선언해서 해결은 했습니다. 맞는 해...
[양승조
] 또 막혔습니다. ㅠㅠ var list = props[i].Ge...
[양승조
] 아. 감사합니다. 어제는 안됐던것 같은데....정신을 차려야겠네...
[정성태] "props[i].GetValue(props[i])" 코드에서 ...
[정성태] 저렇게 조각 코드 말고, 실제로 재현이 되는 예제 프로젝트를 압...
[정성태] Modules 창(Ctrl+Shift+U)을 띄워서, 해당 Op...
[정성태] 만드실 수 있습니다. 단지, Unity 엔진 내의 스크립트와 W...
글쓰기
제목
이름
암호
전자우편
HTML
홈페이지
유형
제니퍼 .NET
닷넷
COM 개체 관련
스크립트
VC++
VS.NET IDE
Windows
Team Foundation Server
디버깅 기술
오류 유형
개발 환경 구성
웹
기타
Linux
Java
DDK
Math
Phone
Graphics
사물인터넷
부모글 보이기/감추기
내용
<div style='display: inline'> <h1 style='font-family: Malgun Gothic, Consolas; font-size: 20pt; color: #006699; text-align: center; font-weight: bold'>windbg 분석 사례 - 종료자(Finalizer)에서 예외가 발생한 경우 비정상 종료(Crash) 발생</h1> <p> 이번엔 일본의 고객사에서 발생한 문제입니다. 웹 애플리케이션이 알 수 없는 이유로 비정상 종료를 한다고 하는데 원인을 모르겠다고 하면서 혹시나 제니퍼 닷넷을 설치하면 알 수 있을까 싶어 설치를 했다고 합니다. 물론! 그 어떤 APM 제품도 "비정상 종료"를 하는 경우에는 그 원인을 잡아낼 수 없습니다. ^^<br /> <br /> 이런 경우, 이미 구매한 고객사에서 문의를 한 것이기 때문에 메모리 덤프를 보내주면 원인을 찾아서 알려드린다고... 일종의 서비스를 제공했습니다. 며칠 후 고객사 측에서 메모리 덤프를 보내줬는데, 이게 좀 문제가 있습니다. Full Memory 덤프를 보내준 것이 아니고 윈도우에서 제공하는 crash 덤프를 보내준 것입니다. 이런 유의 덤프는 windbg에서 로드할 때 다음과 같은 메시지를 볼 수 있습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 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] <span style='color: blue; font-weight: bold'>User Mini Dump File: Only registers, stack and portions of memory are available</span> </pre> <br /> 그래도 약 500MB가 넘는 덤프라서 어느 정도의 정보는 담고 있기 때문에 "!analyze -v" 명령을 이용해 분석을 해봤습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 0:015> <span style='color: blue; font-weight: bold'>!analyze -v</span> ...[생략]... 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 <span style='color: blue; font-weight: bold'>KERNELBASE!RaiseException+0x58:</span> 772bc42d c9 leave Resetting default scope FAULTING_IP: KERNELBASE!RaiseException+58 772bc42d c9 leave EXCEPTION_RECORD: (.exr -1) ExceptionAddress: 772bc42d (KERNELBASE!RaiseException+0x00000058) <span style='color: blue; font-weight: bold'>ExceptionCode: e0434352 (CLR exception)</span> 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> ...[생략]... </pre> <br /> 다른 오류는 없고 위와 같이 CLR Exception 하나가 발생한 후 KERNELBASE!RaiseException이 발생했습니다. 그런데 이게 비정상 종료를 이끌었는지는 확신할 수 없습니다. 그래서 고객사 측에 이 시점의 이벤트 로그를 보내달라고 요청했고 다음은 이에 대한 내용입니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 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() </pre> <br /> 보는 바와 같이 System.ObjectDisposedException가 발생했고 연이은 로그에서,<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 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 </pre> <br /> 비정상 종료가 발생했음을 알려주고 있습니다. 따라서 비정상 종료를 이끈 것이 ObjectDisposedException 예외의 발생으로 인한 것임을 짐작할 수 있습니다.<br /> <br /> <hr style='width: 50%' /><br /> <br /> 그런데 ObjectDisposedException 예외가 발생했다고 해서 왜? 비정상 종료되는 것일까요? 이유는 이벤트 로그에 찍힌 호출 스택을 통해 알 수 있습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 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.<span style='color: blue; font-weight: bold'>Finalize</span>() </pre> <br /> 그렇습니다. 종료자에서 예외가 발생했고 그 종료자는 CLR에서 특별 관리하는 Finalizer 스레드이기 때문입니다. 실제로 간단한 웹 애플리케이션을 만들어 다음과 같이 재현해 볼 수 있습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > // 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"); } } } </pre> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > // 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); } } } </pre> <br /> 위와 같이 2개의 페이지를 만들고 Default.aspx를 방문한 후, doGC.aspx를 방문하면 웹 애플리케이션이 비정상 종료합니다.<br /> <br /> <hr style='width: 50%' /><br /> <br /> 그런데, 고객사의 경우에는 한 가지 더 재미있는 점이 있습니다. 사실 StreamWriter는 Close 시에 내부 stream을 닫고 null 처리를 합니다. 그래서 두 번째 Close를 호출했을 때는 내부 Stream의 Close가 불리지 않으므로 ObjectDisposedException 예외가 발생하지 않습니다. 실제로 다음과 같은 소스 코드로 이를 확인할 수 있습니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 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(); } } } </pre> <br /> 위의 페이지 호출 후 doGC.aspx를 방문하면 FileUtil의 finalizer가 5번 호출되지만 프로세스는 여전히 잘 살아 있습니다. 왜냐하면 ObjectDisposedException이 발생하지 않기 때문입니다. 그렇다면 어떻게 고객사의 웹 애플리케이션에서는 예외가 발생한 것일까요? 가능성을 생각해 본다면 멀티 스레드로 인한 동시 Close 경우를 들 수 있습니다. 그런데 여기서 또 문제가 있는데 종료자를 호출하는 Finalizer 스레드는 프로세스마다 하나씩 배정되므로 다중 스레드 문제일 수는 없습니다.<br /> <br /> 따라서, 굳이 남은 한 가지 가능성을 고려한다면 ASP.NET 요청 스레드에서 Close를 하는 것과 동시에 Finalizer에서 동일한 StreamWriter 인스턴스의 Close를 호출하는 것을 생각할 수 있습니다. 과연 그럴 확률이 얼마나 될지? 응용 프로그램이 사용한 코드 유형에 따라 달라지겠지만 어쨌든 외부에서의 분석 결과는 그렇게 나옵니다.<br /> <br /> <hr style='width: 50%' /><br /> <br /> 이 문제를 해결하려면 어떻게 해야 할까요? 아쉽게도 이것은 2차 스레드에서 발생하는 예외로 인한 종료 현상과는 다릅니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > 비동기 코드 실행 중 예외로 인한 ASP.NET 프로세스 비정상 종료 현상 ; <a target='tab' href='http://www.sysnet.pe.kr/2/0/11383'>http://www.sysnet.pe.kr/2/0/11383</a> ASP.NET 응용 프로그램이 예외로 프로세스가 종료된다면? ; <a target='tab' href='http://www.sysnet.pe.kr/2/0/10863'>http://www.sysnet.pe.kr/2/0/10863</a> </pre> <br /> 따라서 aspnet.config 파일의 legacyUnhandledExceptionPolicy 옵션 설정과는 무관합니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > <legacyUnhandledExceptionPolicy enabled="true" /> </pre> <br /> 남은 방법은, 간단합니다. 그냥 종료자에서 예외가 발생하지 않도록 try/catch로 감싸는 것입니다.<br /> <br /> <pre style='margin: 10px 0px 10px 10px; padding: 10px 0px 10px 10px; background-color: #fbedbb; overflow: auto; font-family: Consolas, Verdana;' > public class FileUtil { // ...[생략]... ~FileUtil() { try { // ...[생략]... throw new ApplicationException(); } catch { } } } </pre> <br /> 그러니까, 절대로 Finalizer 내에서는 예외를 발생시켜서는 안 됩니다.<br /> <br /> (첨부 파일은 이 글의 예제 코드를 포함합니다.)<br /> <br /> <hr style='width: 50%' /><br /> <br /> 참고로, 해당 고객사에서는 FileUtil.Finalize에서 StreamWriter.Close를 굳이 호출할 필요는 없었습니다. 왜냐하면 Managed 자원은 Finalize에서 처리하지 않아도 참조가 없어지면 GC가 되기 때문입니다. 즉, Native 자원을 처리하는 것이 아니므로 굳이 구현할 필요가 없었던 Finalize로 인해 웹 응용 프로그램이 장애가 발생한 것입니다.<br /> <br /> 그나저나, 엄밀히 따지면 이 글은 windbg 분석 글은 아닙니다. ^^ 단지 굳이 어렵게 windbg 분석 없이도 이벤트 로그 만으로 해결할 수 있는 문제도 많다는 것을 말하고 싶었습니다. 게다가 일본의 그 고객사도 조금만 여유를 가지고 이벤트 로그의 내용을 자세히 봤다면 그 원인을 어렵지 않게 찾고, 또한 고칠 수 있었을 것입니다.<br /> </p><br /> <br /><hr /><span style='color: Maroon'>[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]</span> </div>
첨부파일
스팸 방지용 인증 번호
1192
(왼쪽의 숫자를 입력해야 합니다.)