TFS 오류 추적(TF53010, TF14105)
요즘... 제 TFS 서버 상태가 말이 아니군요. 이거저거 계정 지워가면서 임의로 DB 레코드 지워가다 보니, 아무리 테스트를 위한 TFS 서버라지만 왠지 제가 너무했다는 생각이 들 정도입니다. ^^; 그러다 보니, 이번에 설명하는 상황은 매우 특수할 수 있기 때문에 여러분들이 이와 같은 오류 상황을 겪을 일은 매우 드물긴 하겠지만, 저 스스로의 문제 해결의 흐름을 기억해 두기 위해서라도 이렇게 토픽으로 남겨봅니다.
어쨌든, 최근에 제가 TFS를 완전히 엉망으로 만들어 놨던 것은, 얼마 전 "TF10217, TF53010, TF14105 오류" 문제를 해결하는 과정에서 제가 임의로 삭제했던 DB 레코드들로 인한 것이었습니다. 그 토픽에서 소개했던 "View History Errors"에서 설명된 해결 방법을 따르지 않고, 없어진 OwnerId에 해당하는 모든 tbl_Changeset의 레코드를 전부 "Delete From..."으로 삭제했더니... ^^; 그 이후로, 이벤트 로그에는 1시간마다 다음과 같은 오류가 남기 시작했습니다.
이벤트 형식: 오류
이벤트 원본: TFS Version Control
이벤트 범주: 없음
이벤트 ID: 3000
날짜: 2007-03-03
시간: 오후 9:08:37
사용자: N/A
컴퓨터: WIN2003TEST
설명:
TF53010: An unexpected condition has occurred in a Team Foundation component. The information contained here should be made available to your site administrative staff.
Technical Information (for the administrative staff):
Date (UTC): 2007-03-03 오후 12:08:37
Machine: WIN2003TEST
Application Domain: /LM/W3SVC/3/Root/VersionControl-3-128173432737780965
Assembly: Microsoft.TeamFoundation.Common, Version=8.0.0.0, Culture=neutral, PublicKeyToken=b03f5f7f11d50a3a; v2.0.50727
Process Details:
Process Name: w3wp
Process Id: 4996
Thread Id: 2244
Account name: TESTDOMAIN\TFSTEST
Detailed Message: TF14105: An exception occurred in the Team Foundation Source Control System.
Web Request Details
Url: https://www.sysnet.pe.kr:8070/VersionControl/v1.0/repository.asmx [method: POST]
User Agent: Team Foundation (w3wp.exe[Data Warehouse], 8.0.50727.762)
Headers: Content-Length...[중간생략]...e-1812-412b-943f-4fbddda715ae
Path: /VersionControl/v1.0/repository.asmx
Local Request: False
Host Address: 192.168.1.100
User: TESTDOMAIN\TFSTEST [authentication type: NTLM]
Exception Message: Invalid attempt to read when no data is present. (type InvalidOperationException)
Exception Stack Trace: at System.Data.SqlClient.SqlDataReader.ReadColumnHeader(Int32 i)
at System.Data.SqlClient.SqlDataReader.IsDBNull(Int32 i)
at Microsoft.TeamFoundation.Server.SqlColumnBinder.GetDateTime(SqlDataReader reader)
at Microsoft.TeamFoundation.VersionControl.Server.VersionedItemComponent.ChangesetColumns.bind(SqlDataReader reader)
at Microsoft.TeamFoundation.VersionControl.Server.VersionedItemComponent.QueryChangeset(Int32 changeset, Boolean includeChanges, IList changes, Changeset& changesetInfo)
at Microsoft.TeamFoundation.VersionControl.Server.Changeset.QueryChangeset(IPrincipal userPrincipal, Int32 changeset, Boolean includeChanges, Boolean generateDownloadUrls)
at Microsoft.TeamFoundation.VersionControl.Server.Repository.QueryChangeset(Int32 changesetId, Boolean includeChanges, Boolean generateDownloadUrls)
원인은, TFSServerScheduler가 해당 요청을 1시간마다 주기적으로 발생시키는 것에서 기인했습니다.
문제는 단지 TFSServerScheduler에 대한 요청을 정상적으로 처리하지 못한 것만이 아니었습니다. 애석하게도, "팀 프로젝트"로 등록된 것들 중 몇 개는 그와 연결된 "소스 컨트롤"을 열려고 하면 아래와 같은 에러를 내면서 진행이 되지 않았습니다.
"
Configure Source Control
Either source control has not been configured for this team project or
you do not have permission to access it. Would you like to create the
source control folder, $/SysnetSite?
"
게다가 해당 소스 컨트롤에 등록된 솔루션 프로젝트를 열려고 하면 아래와 같은 에러 메시지가 뜨고.
"
The solution appears to be under source control, but its binding information cannot be found. Because it is not
possible to recover this missing information automatically, the projects whose bindings are missing will be treated as
not under source control.
"
물론, "Source Control Explorer"에는 아래와 같이 등록되어 있으며, 그 중의 아무 파일이나 "check-out"을 하려고 하면 다음과 같은 오류 메시지가 "Output" 윈도우에 남게 됩니다.
"
TF10175: The team project folder $/SysnetSite does not exist.
Contact your Team Foundation Server administrator and ask that it be created.
"
심지어, 아래와 같이 Workspace 관리창에서 현재 등록된 Team Project 목록에도 누락되어 있습니다. (보시는 것처럼, "SysnetSite" 팀 프로젝트가 목록에 없습니다.)
일단, 문제 자체는 "Changeset" 테이블에서 삭제된 changeset 레코드들을 다시 복원하면 그만이었지만. 저는 그 실수를 전혀 모르는 상태라는 가정으로 이 문제를 풀어보고 싶었습니다.
우선, 이벤트 로그를 살펴보면 Process ID는 4996이고, 발생한 예외는 "InvalidOperationException"임을 알 수 있습니다. 이 정보를 바탕으로 문제를 추적하기 위한 2가지의 방법이 생각났습니다. 하나는 WinDBG를 이용하여 "Microsoft.TeamFoundation.VersionControl.Server.Repository.QueryChangeset" 메서드가 실행될 때의 인자값을 확인하는 것과, 또 하나는 HttpModule을 web.config에 등록해서 "QueryChangeset" 메서드를 담고 있는 repository.asmx가 호출될 때의 인자값을 확인하는 방법입니다.
이번에는 ^^ 그동안의 토픽들(Main Method에 Break Point 걸기, Managed Method에 Break Point 걸기, 예외 발생 시 Minidump 생성 - WinDBG)에 대한 실습 삼아서 WinDBG로 알아내는 것을 선택해 보았습니다.(사실 ^^ 바로 이번 이야기를 위해서 그와 같은 토픽들을 써온 것이었습니다.)
처음에는 미니덤프를 떠서 확인해 보려고 했습니다. 이벤트 로그의 내용을 기반으로 windbg를 실행시킨 후, "File" / "Attach to Process..." 메뉴를 이용하여 PID 값이 "4996"인 w3wp.exe에 디버거를 연결시켰습니다. 그리고는, ".loadby sos mscorwks" 명령어등의 기초 작업을 한 후, "!soe" 확장 명령어를 다음과 같이 실행시켰습니다.
!soe -create System.InvalidOperationException 1
이어서, "Debug" / "Event Filters..." 메뉴를 선택하여 "CLR exception"의 "Commands..." 설정을 다음으로 대체했습니다.
!soe System.InvalidOperationException 1;.if(@$t1==0) {g} .else {.dump /ma /u c:\\temp\\ANE.dmp;}
자... 이제 여유를 가지고 ^^ 예외가 발생할 때까지 (1시간마다 발생했으니) 기다리면 됩니다. 그러면, "System.InvalidOperationException" 예외가 발생하자마자 다음과 같은 내용이 windbg 화면에 출력되면서 미니덤프 파일이 남겨지게 됩니다.
(1384.1474): CLR exception - code e0434f4d (first chance)
Creating c:\\temp\\ANE_1778_2007-03-02_01-15-17-452_1384.dmp - mini user dump
Dump successfully written
First chance exceptions are reported before any exception handling.
This exception may be expected and handled.
eax=05afebe0 ebx=048ca748 ecx=00000000 edx=00000025 esi=05afec6c edi=e0434f4d
eip=7c815e02 esp=05afebdc ebp=05afec30 iopl=0 nv up ei pl nz na po nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000202
kernel32!RaiseException+0x53:
7c815e02 5e pop esi
자... 이제 "c:\\temp\\ANE_1778_2007-03-02_01-15-17-452_1384.dmp" 파일을 자신의 개발 환경에 복사한 후 windbg.exe에서 "File" / "Open Crash Dump..." 메뉴를 통해 로드를 합니다. 그다음 역시 ".loadby sos mscorwks" 명령 후 "!clrstack -a" 명령을 실행하니 다음과 같은 결과가 나왔습니다.
0:018> !loadby sos mscorwks
0:018> !clrstack -a
OS Thread Id: 0x1474 (18)
ESP EIP
05afecb8 7c815e02 [HelperMethodFrame: 05afecb8]
05afed5c 6539fdcc System.Data.SqlClient.SqlDataReader.ReadColumnHeader(Int32)
PARAMETERS:
this = <no data>
i = <no data>
LOCALS:
<no data>
...[중간 생략]...
05afee68 009c0783 Microsoft.TeamFoundation.VersionControl.Server.Repository.QueryChangeset(Int32, Boolean, Boolean)
PARAMETERS:
this = 0x0304cacc
changesetId = <no data>
includeChanges = <no data>
generateDownloadUrls = <no data>
LOCALS:
<no data>
0x05afee80 = 0x00000000
...[중간 생략]...
05aff5d0 65fbc567 System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr, Int32)
05aff780 79f1ef33 [ContextTransitionFrame: 05aff780]
05aff7d0 79f1ef33 [GCFrame: 05aff7d0]
05aff928 79f1ef33 [ComMethodFrame: 05aff928]
아... 이런... 실망이군요. 왜 changesetId, includeChanges, generateDownloadUrls 인자들의 값이 미니덤프에는 없는 걸까요? 덤프 옵션도 "/ma"로 했는데... 혹시 이 부분에 대해서 의견주실 분이 계시면 ^^ 댓글 부탁드리겠습니다.
어쨌든, 미니덤프는 예외가 발생했을 때는 이미 시점이 늦은 것 같고, 아마도 "QueryChangeset" 메서드가 실행되는 시점에는 가능하지 않을까 라는 생각이 들어서, 다시 w3wp.exe에 디버거를 연결해서 다음과 같이 "QueryChangeset"에 대해서 정지점을 걸었습니다.
0:027> !bpmd Microsoft.TeamFoundation.VersionControl.Server.DLL Microsoft.TeamFoundation.VersionControl.Server.Repository.QueryChangeset
Found 1 methods...
MethodDesc = 05882be8
Setting breakpoint: bp 05BDC0D8 [Microsoft.TeamFoundation.VersionControl.Server.Repository.QueryChangeset(Int32, Boolean, Boolean)]
0:027> g
Breakpoint 0 hit
eax=0754eb60 ebx=0754eadc ecx=0798c1ac edx=000000e7 esi=054abff8 edi=00000000
eip=05bdc0d8 esp=0754eaac ebp=0754eac0 iopl=0 nv up ei pl zr na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246
05bdc0d8 55 push ebp
다행히도, 이번에는 인자값을 다음과 같이 확인할 수 있었습니다.
0:022> !clrstack -a
OS Thread Id: 0x10ac (22)
ESP EIP
0754eaac 05bdc0d8 Microsoft.TeamFoundation.VersionControl.Server.Repository.QueryChangeset(Int32, Boolean, Boolean)
PARAMETERS:
this = 0x0798c1ac
changesetId = 0x000000e7 // 231
includeChanges = 0x00000001
generateDownloadUrls = 0x00000000
LOCALS:
<no data>
<no data>
... [생략]...
이제, 해당 changesetId 값대로 "TfsVersionControl" DB의 "tbl_ChangeSet"에서 231번 값을 갖는 레코드를 확인해 봤습니다. 당연히 ^^ 없었습니다. 이제부터가 문제군요. ^^; 함부로 삭제했던 "tbl_ChangeSet" 테이블 내용을 채워넣어야 하는데 어떤 값들을 채워야 할지 고민이 되었습니다. 그나저나... "QueryChangeset"을 포함한 asmx를 호출하는 TFSServerScheduler가 어떻게 해당 ChangesetId 값들을 알수 있었을 까 싶어서, 다른 DB의 테이블들을 찾아보았습니다. 오... 다행히도 "TFSWarehouse" DB의 "Changeset" 테이블이 있는 것이 눈에 띄였습니다. 이제부턴 간단하지요! "tbl_ChangeSet" 테이블에 삭제된 값들을 "Changeset" 테이블로부터 모두 가져왔습니다.
대충 다음과 같은 식으로 내용을 채웠습니다.
tbl_ChangeSet
ChangeSetId : TFSWarehouse DB의 "Changeset" 테이블에 있는 ChangeSet ID 필드로부터 값을 가져옴
OwnerId : TfsVersionControl DB의 "tbl_Identity" 테이블에 있는 적절한 IdentityId 필드로부터 값을 가져옴
CreateDate : : TFSWarehouse DB의 "Changeset" 테이블에 있는 __LastUpdatedTime 필드로부터 값을 가져옴
Comment : NULL
ExtendedComment : NULL
CheckInNoteId : 기존 값들 중 하나
CommitterId : OwnerId 값과 동일하게 설정.
물론, 두말할 필요도 없겠지만 백업 받아둔 것이 있다면 거기서 복구하시는 것이 좋겠지요. ^^; (애석하게도 저는 VPC 단위로 복사만 해두었을 뿐, DBA 수준의 백업은 하지 않고 있었습니다. 음... 이해해주십시오. 테스트 환경입니다. ^^)
휴... 이렇게 하고 나서야 1시간마다 남겨지는 이벤트 로그 오류는 사라지게 되었습니다.
그래도, 약간의 문제가 더 있었습니다. 기존에 "없어진 것"으로 취급되었던 팀 프로젝트들에 연결되어 있던 솔루션을 VS.NET 2005에서 열려고 했을 때 발생하던 다음의 오류는 계속 나타났습니다.
"Source Control Explorer"에서 Workspace에 대해 WorkingFolder를 수동으로 매핑시키려고 해도 다음과 같은 오류가 발생하면서 더 이상 진행할 수 없었습니다.
"
The working folder '...' is already in use by
another workspace on this computer.
"
휴... 가능한 더 이상 DB 레코드를 직접 건드리기 싫지만, 어쩔 수 없게 되었습니다. 우선, "TfsVersionControl" DB의 "tbl_WorkingFolder" 테이블을 검사해보니, 다행히 문제의 원인을 알 수 있었습니다. 다음 그림과 같이 "WorkspaceId" 값이 현재는 존재하지 않는 값들로 (여기서는 1) 채워져 있었습니다.
그래서, tbl_Workspace의 OwnerId 값이 제 계정으로 되어 있는 WorkspaceId 값을 "tbl_WorkingFolder"의 "WorkspaceId" 값으로 업데이트를 했습니다. 와~~~ ^^ 이제서야 모든 문제가 해결되었습니다.
[이 토픽에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]