This morning I was setting up to move some new code I had written as an initial experiment into a new codebase, which is stored using Team Foundation Version Control (TFVC) in Visual Studio Team Services (VSTS). Before I could do that, I needed to go and update my local workspace to the latest version.
Unfortunately, Visual Studio 2017 was not being cooperative, and would get stuck with the “downloading files” dialog open everytime I tried it. So I decided to give TF.exe a try and see if the command line tool was doing the same. It was.
Annoyed with it, and with my search-fu failing me, I decided to attach trusty old WinDBG to the hung instance of TF.exe. What were the threads doing?
DbgId ThreadId ClrThread Apartment Kind Action
===== ======== ========= ========= ========== ===================================================================================================
0 31c4 104d2d0 STA MonitorWait: Microsoft.TeamFoundation.VersionControl.Client.AsyncOperation.WaitForCompletion(Int32)
2 1b98 105b6b8 MTA Finalizer
6 6bc 637a078 MTA Worker (idle)
7 2854 637b690 Worker (idle)
9 7f10 63adef8 MTA Background WaitHandle.WaitAny: 0x00000000040708bc
12 4ec 71f7d00 MTA IO
13 71e4 7232520 MTA Worker WaitHandle.WaitOne: 0x0000000003eacd64
Thread 12 didn’t seem to be relevant. Thread 13, however, seemed to be stuck on a file async operation:
DbgId ThreadId Apartment Kind CLR GC Mode GC Suspending?
13 71e4 MTA Worker v4.7.2098.00 Preemptive no
WaitHandle.WaitOne
------------------
WaitHandle Type Microsoft.Win32.SafeHandles.SafeWaitHandle
WaitHandle Address 0x0000000003eacd64
SP IP Function
08b5eb44 00000000 HelperMethodFrame_1OBJ [System.Threading.WaitHandle.WaitOneNative(System.Runtime.InteropServices.SafeHandle, UInt32, Boolean, Boolean)]
08b5ec28 72092f71 System.Threading.WaitHandle.InternalWaitOne(System.Runtime.InteropServices.SafeHandle, Int64, Boolean, Boolean)
08b5ec40 72092f38 System.Threading.WaitHandle.WaitOne(Int32, Boolean)
08b5ec54 72092fc2 System.Threading.WaitHandle.WaitOne()
08b5ec5c 720d16d9 System.IO.FileStreamAsyncResult.Wait()
08b5ec7c 7208769b System.IO.FileStream.EndWrite(System.IAsyncResult)
08b5ec8c 720b76ce System.IO.FileStream.FlushWrite(Boolean)
08b5ec9c 721267ee System.IO.FileStream.Dispose(Boolean)
08b5ecbc 72126786 System.IO.Stream.Close()
08b5ecc8 0f48294c Microsoft.TeamFoundation.VersionControl.Client.UploadDownload.DownloadBeginReadCallback(System.IAsyncResult)
08b5ed6c 713e83e9 System.Net.LazyAsyncResult..ctor(System.Object, System.Object, System.AsyncCallback, System.Object)
08b5ed80 713e829b System.Net.ConnectStream.BeginReadWithoutValidation(Byte[], Int32, Int32, System.AsyncCallback, System.Object)
08b5eddc 713e8193 System.Net.ConnectStream.BeginRead(Byte[], Int32, Int32, System.AsyncCallback, System.Object)
08b5ee04 0f483d6c Microsoft.TeamFoundation.VersionControl.Client.UploadDownload.DecompressAndWriteChunk(DownloadAsyncResult)
08b5ee20 0f4839e1 Microsoft.TeamFoundation.VersionControl.Client.UploadDownload.DownloadDestBeginWriteCallback(System.IAsyncResult)
08b5ee4c 720d1867 System.IO.FileStreamAsyncResult.CallUserCallbackWorker()
08b5ee58 720d1838 System.IO.FileStreamAsyncResult+<>c.<CallUserCallback>b__39_0(System.Object)
08b5ee5c 720705c2 System.Threading.QueueUserWorkItemCallback.WaitCallback_Context(System.Object)
08b5ee64 72109a4a System.Threading.ExecutionContext.RunInternal(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
08b5eed4 72109956 System.Threading.ExecutionContext.Run(System.Threading.ExecutionContext, System.Threading.ContextCallback, System.Object, Boolean)
08b5eee8 720714c0 System.Threading.QueueUserWorkItemCallback.System.Threading.IThreadPoolWorkItem.ExecuteWorkItem()
08b5eefc 72070c22 System.Threading.ThreadPoolWorkQueue.Dispatch()
08b5ef4c 72070a8a System.Threading._ThreadPoolWaitCallback.PerformWaitCallback()
08b5f170 00000000 DebuggerU2MCatchHandlerFrame
Looking at the async operation, we see indeed it’s not complete, even after minutes of waiting:
0x03ff028c System.IO.FileStreamAsyncResult
[statics]
0000 _userCallback : NULL
0004 _userStateObject : NULL
0008 _waitHandle : 03ff02bc (System.Threading.ManualResetEvent)
000c _handle : 03fd7814 (Microsoft.Win32.SafeHandles.SafeFileHandle)
0010 _overlapped : 03e90fd8 (System.UIntPtr)
0014 _EndXxxCalled : 1 (System.Int32)
0018 _numBytes : 0 (System.Int32)
001c _errorCode : 0 (System.Int32)
0020 _numBufferedBytes : 0 (System.Int32)
0024 _isWrite : True (System.Boolean)
0025 _isComplete : False (System.Boolean)
0026 _completedSynchronously : False (System.Boolean)
So clearly, the hang is happening because the async operation to close one of the .gz files used when downloading changes is never completing.
Where does this leave me? Nowhere, really, since I still have no clue why the file close is never completing. However, spending some quality time in WinDBG sure is better than throwing my laptop out the window!
Up next: Wiping my local workspace and spending 1+ hour downloading everything again.
