SQL Server Import and Export Wizard blowing up due to an unexpected error
Somebody was trying to run the SQL Server Import and Export Wizard (DTSWizard.exe) in one of his machines, but when he clicked Next on the first (welcome) dialog, it showed the following error:
===================================
This wizard will close because it encountered the following error: (Microsoft SQL Server)
------------------------------
For help, click: http://go.microsoft.com/fwlink?ProdName=Microsoft+SQL+Server&ProdVer=9.00.3042.00&EvtSrc=Microsoft.SqlServer.Management.UI.WizardFrameworkErrorSR&EvtID=UncaughtException&LinkId=20476
===================================
The specified module could not be found. (Exception from HRESULT: 0x8007007E) (Microsoft.SqlServer.DTSRuntimeWrap)
------------------------------
Program Location:
at Microsoft.SqlServer.Dts.Runtime.Wrapper.ApplicationClass.get_DBProviderInfos()
at Microsoft.SqlServer.Dts.DtsWizard.DTSWizard.GetDtsDbProviderInfos(WizardInputs wizardInputs)
at Microsoft.SqlServer.Dts.DtsWizard.DataSourceCombo.PopulateProviders(Boolean fSources, WizardInputs wizardInputs)
at Microsoft.SqlServer.Dts.DtsWizard.Step1.OnInitializePage(EventArgs e)
at Microsoft.SqlServer.Management.UI.WizardPage.RaiseEnterPage()
at Microsoft.SqlServer.Management.UI.WizardForm.NextPage(WizardPage nextPage)
at Microsoft.SqlServer.Management.UI.WizardForm.Next_Click(Object sender, EventArgs e)
So they asked me for help to try to diagnose what could have caused the following error in a particular environment.
I started by having a quick look to the source code and found that we were relying on ISourcesRowset::GetSourcesRowset from the Root Enumerator Object to do the job of enumerating the different providers available in the machine. That already made me suspect this had to do with some problem with their installation of MDAC, but had to prove it or they wouldn't believe me otherwise. :-)
Therefore I 1) launched the SQL Server Import and Export Wizard, 2) attached WinDBG (from the Debugging Tools for Windows) to the wizard process (DTSWizard.exe), 3) set a breakpoint on the function I had seen in the code of the Data Transformation Runtime (DTS.dll) that was going to enumerate the providers (i.e. DTS!CDBProviderInfos::EnumerateOLEDBSources), and 4) asked the debugger to resume the execution of the debuggee it was attached to by using the g command from the debugger command window.
Then I clicked the Next button on the first dialog of the wizard and, as expected, the breakpoint was hit. So the command window showed this:
0:011> r
eax=00000000 ebx=03b286f4 ecx=22761069 edx=03f87584 esi=03b28628 edi=03b28688
eip=227728b6 esp=064af810 ebp=064af838 iopl=0 nv up ei pl zr na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246
DTS!CDBProviderInfos::EnumerateOLEDBSources:
227728b6 6808010000 push 108h
Notice it was thread instance 11 the one which was trying to run that function, and notice that it was being run on this thread because it was a COM component being invoked from another thread on a different apartment:
0:011> k
ChildEBP RetAddr
064af838 77e799dc DTS!CDBProviderInfos::EnumerateOLEDBSources
064af854 77ef321a RPCRT4!Invoke+0x30
064afc58 77ef4ea5 RPCRT4!NdrStubCall2+0x297
064afcb0 77132a57 RPCRT4!CStdStubBuffer_Invoke+0x3f
064afcd4 77600c31 oleaut32!CUnivStubWrapper::Invoke+0xc5
064afd14 77600bdb ole32!SyncStubInvoke+0x33
064afd5c 7750f237 ole32!StubInvoke+0xa7
064afe34 7750f15c ole32!CCtxComChnl::ContextInvoke+0xe3
064afe50 77600b11 ole32!MTAInvoke+0x1a
064afe80 776009bc ole32!AppInvoke+0x9c
064aff54 77600df2 ole32!ComInvokeWithLockAndIPID+0x2e0
064aff80 7750fcb3 ole32!ComInvoke+0x60
064aff94 774fe3dc ole32!ThreadDispatch+0x23
064affa8 774fe444 ole32!CRpcThread::WorkerLoop+0x1e
064affb4 7c80b683 ole32!CRpcThreadCache::RpcWorkerThreadEntry+0x1b
064affec 00000000 KERNEL32!BaseThreadStart+0x37
Let's see what thread 0, our UI thread was doing by 1) setting the context on that thread (~0s):
0:011> ~0s
eax=00000001 ebx=0012e3a4 ecx=0012e618 edx=7c90eb94 esi=00000000 edi=7ffd8000
eip=7c90eb94 esp=0012e37c ebp=0012e418 iopl=0 nv up ei pl zr na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246
ntdll!KiFastSystemCallRet:
7c90eb94 c3 ret
2) dumping its managed stack (using !clrstack from the sos.dll debugging extension):
0:000> !clrstack
OS Thread Id: 0x11d0 (0)
ESP EIP
0012ebf4 7c90eb94 [ComPlusMethodFrameGeneric: 0012ebf4] Microsoft.SqlServer.Dts.Runtime.Wrapper.ApplicationClass.get_DBProviderInfos()
0012ec04 2cc438ef Microsoft.SqlServer.Dts.DtsWizard.DTSWizard.GetDtsDbProviderInfos(Microsoft.SqlServer.Management.UI.WizardInputs)
0012ec10 2cc49793 Microsoft.SqlServer.Dts.DtsWizard.DataSourceCombo.PopulateProviders(Boolean, Microsoft.SqlServer.Management.UI.WizardInputs)
0012ec4c 2cc3403c Microsoft.SqlServer.Dts.DtsWizard.Step1.OnInitializePage(System.EventArgs)
0012ec58 4df0deb6 Microsoft.SqlServer.Management.UI.WizardPage.RaiseEnterPage()
0012ec60 4df0b1d6 Microsoft.SqlServer.Management.UI.WizardForm.NextPage(Microsoft.SqlServer.Management.UI.WizardPage)
0012ec70 4df0b076 Microsoft.SqlServer.Management.UI.WizardForm.Next_Click(System.Object, System.EventArgs)
0012eca8 7b060bdb System.Windows.Forms.Control.OnClick(System.EventArgs)
0012ecb8 7b1292e9 System.Windows.Forms.Button.OnClick(System.EventArgs)
0012ecc4 7b1293ef System.Windows.Forms.Button.OnMouseUp(System.Windows.Forms.MouseEventArgs)
0012ece8 7b0f68c6 System.Windows.Forms.Control.WmMouseUp(System.Windows.Forms.Message ByRef, System.Windows.Forms.MouseButtons, Int32)
0012ed34 7b074fef System.Windows.Forms.Control.WndProc(System.Windows.Forms.Message ByRef)
0012ed38 7b0841ce [InlinedCallFrame: 0012ed38]
0012edd4 7b0840eb System.Windows.Forms.Button.WndProc(System.Windows.Forms.Message ByRef)
0012eddc 7b07d24d System.Windows.Forms.Control+ControlNativeWindow.OnMessage(System.Windows.Forms.Message ByRef)
0012ede0 7b07d226 System.Windows.Forms.Control+ControlNativeWindow.WndProc(System.Windows.Forms.Message ByRef)
0012edf4 7b07d035 System.Windows.Forms.NativeWindow.Callback(IntPtr, Int32, IntPtr, IntPtr)
0012f1d4 003920a4 [NDirectMethodFrameStandalone: 0012f1d4] System.Windows.Forms.UnsafeNativeMethods.DispatchMessageW(MSG ByRef)
0012f1e4 7b0872ce System.Windows.Forms.Application+ComponentManager.System.Windows.Forms.UnsafeNativeMethods.IMsoComponentManager.FPushMessageLoop(Int32, Int32, Int32)
0012f284 7b086e95 System.Windows.Forms.Application+ThreadContext.RunMessageLoopInner(Int32, System.Windows.Forms.ApplicationContext)
0012f2f0 7b086cd3 System.Windows.Forms.Application+ThreadContext.RunMessageLoop(Int32, System.Windows.Forms.ApplicationContext)
0012f320 7b240b6e System.Windows.Forms.Form.ShowDialog(System.Windows.Forms.IWin32Window)
0012f400 7b24066f System.Windows.Forms.Form.ShowDialog()
0012f404 4df059c8 Microsoft.SqlServer.Management.UI.WizardForm.ShowDialog()
0012f434 2cc423d9 Microsoft.SqlServer.Dts.DtsWizard.DTSWizard.Main(System.String[])
0012f69c 79e7be1b [GCFrame: 0012f69c]
and 3) dumping its native stack (k). This last step reveals that the managed function Microsoft.SqlServer.Dts.Runtime.Wrapper.ApplicationClass.get_DBProviderInfos (from the stack above), was waiting for a COM call to respond (and that's the call we saw thread 11 was taking care of):
0:000> k
ChildEBP RetAddr
0012e378 7c90e9ab ntdll!KiFastSystemCallRet
0012e37c 7c8094e2 ntdll!ZwWaitForMultipleObjects+0xc
0012e418 7e4195f9 KERNEL32!WaitForMultipleObjectsEx+0x12c
0012e474 77512235 USER32!RealMsgWaitForMultipleObjectsEx+0x13e
0012e49c 7751235c ole32!CCliModalLoop::BlockFn+0x80
0012e4c4 77526749 ole32!ModalLoop+0x5b
0012e4d4 77601f01 ole32!SwitchSTA+0x21
0012e4f4 7760109a ole32!CRpcChannelBuffer::SwitchAptAndDispatchCall+0xd1
0012e5d4 77512409 ole32!CRpcChannelBuffer::SendReceive2+0xb9
0012e5f0 775123b2 ole32!CCliModalLoop::SendReceive+0x1e
0012e65c 77510414 ole32!CAptRpcChnl::SendReceive+0x6f
0012e6b0 77ef3db5 ole32!CCtxComChnl::SendReceive+0x113
0012e6cc 77ef3ead RPCRT4!NdrProxySendReceive+0x43
0012eaa8 77ef3e42 RPCRT4!NdrClientCall2+0x1fa
0012eac8 77e8a7f3 RPCRT4!ObjectStublessClient+0x8b
0012ead8 79f36750 RPCRT4!ObjectStubless+0xf
0012eba0 036a1ed6 mscorwks!CLRToCOMWorker+0x196
WARNING: Frame IP not in any known module. Following frames may be wrong.
0012ebdc 2cc438ef 0x36a1ed6
0012ec40 2cc3403c DTSWizard_ni!GetSourceTransformName+0x2f
0012ec9c 7b060bdb DTSWizard_ni!InitializeComponent+0x176
So, let's move back to thread 11:
0:000> ~11s
eax=00000000 ebx=03b286f4 ecx=22761069 edx=03f87584 esi=03b28628 edi=03b28688
eip=227728b6 esp=064af810 ebp=064af838 iopl=0 nv up ei pl zr na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246
DTS!CDBProviderInfos::EnumerateOLEDBSources:
227728b6 6808010000 push 108h
And disassemble its code from the beginning to the point I am suspecting it could be failing. That point is where we try to create an instance of the class with ID CLSID_OLEDB_ENUMERATOR (i.e. the root enumerator object I referred to, earlier). Notice that at the very beginning we store in the esi register the pointer to the COM API CoCreateInstance, and at some point we call that function, to create an instance of CLSID_OLEDB_ENUMERATOR:
0:011> u .
DTS!CDBProviderInfos::EnumerateOLEDBSources:
227728b6 6808010000 push 108h
227728bb b814ce7922 mov eax,offset DTS!_chkstk+0x83d4 (2279ce14)
227728c0 e86c1f0200 call DTS!_EH_prolog3_catch (22794831)
227728c5 8b35c8146f22 mov esi,dword ptr [DTS!_imp__CoCreateInstance (226f14c8)]
227728cb 8d45e4 lea eax,[ebp-1Ch]
227728ce 50 push eax
227728cf 68bc186f22 push offset DTS!IID_IDBInitialize (226f18bc)
227728d4 33db xor ebx,ebx
0:011> u
DTS!CDBProviderInfos::EnumerateOLEDBSources+0x20:
227728d6 6a15 push 15h
227728d8 53 push ebx
227728d9 68081b7022 push offset DTS!CLSID_DTSFlatFile (22701b08)
227728de 895dd4 mov dword ptr [ebp-2Ch],ebx
227728e1 895dd8 mov dword ptr [ebp-28h],ebx
227728e4 895de4 mov dword ptr [ebp-1Ch],ebx
227728e7 ffd6 call esi
227728e9 33c9 xor ecx,ecx
0:011> u
DTS!CDBProviderInfos::EnumerateOLEDBSources+0x35:
227728eb 3bc3 cmp eax,ebx
227728ed 8b45e4 mov eax,dword ptr [ebp-1Ch]
227728f0 0f9dc1 setge cl
227728f3 3bc3 cmp eax,ebx
227728f5 8bf9 mov edi,ecx
227728f7 7406 je DTS!CDBProviderInfos::EnumerateOLEDBSources+0x49 (227728ff)
227728f9 8b08 mov ecx,dword ptr [eax]
227728fb 50 push eax
0:011> u
DTS!CDBProviderInfos::EnumerateOLEDBSources+0x46:
227728fc ff5108 call dword ptr [ecx+8]
227728ff 8d45c8 lea eax,[ebp-38h]
22772902 50 push eax
22772903 689c186f22 push offset DTS!IID_ISourcesRowset (226f189c)
22772908 6a01 push 1
2277290a 53 push ebx
2277290b 683c1c6f22 push offset DTS!CLSID_OLEDB_ENUMERATOR (226f1c3c)
22772910 897ddc mov dword ptr [ebp-24h],edi
0:011> u
DTS!CDBProviderInfos::EnumerateOLEDBSources+0x5d:
22772913 895dc8 mov dword ptr [ebp-38h],ebx
22772916 ffd6 call esi
22772918 3bc3 cmp eax,ebx
2277291a 0f8c3a020000 jl DTS!CDBProviderInfos::EnumerateOLEDBSources+0x2a4 (22772b5a)
22772920 8b45c8 mov eax,dword ptr [ebp-38h]
22772923 8d55e8 lea edx,[ebp-18h]
22772926 52 push edx
22772927 53 push ebx
So, following my instinct (or I should say, trying to prove the problem was due to what I thought it was the cause), I let the debuggee continue running to the point where we were about to call CoCreateInstance to create an instance of the root enumerator object and get back a pointer to its ISourcesRowset interface. That was at address 22772916 (see the unassembled code above):
0:011> g 22772916
eax=064af7d4 ebx=00000000 ecx=2331506f edx=23334f74 esi=774ffac3 edi=00000001
eip=22772916 esp=064af6d4 ebp=064af80c iopl=0 nv up ei ng nz ac po cy
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000293
DTS!CDBProviderInfos::EnumerateOLEDBSources+0x60:
22772916 ffd6 call esi {ole32!CoCreateInstance (774ffac3)}
When I get to that point, I run the CoCreateInstance call as if it were a single instruction (command p in the debugger, step over), and found it returned 0x8007007E. That HRESULT represents a Win32 error (you can deduct that based on the presence of the FACILITY_WIN32 flag. For more information on this, see HRESULT_FROM_WIN32):
0:011> p
eax=8007007e ebx=00000000 ecx=03e9220c edx=00000000 esi=774ffac3 edi=00000001
eip=22772918 esp=064af6e8 ebp=064af80c iopl=0 nv up ei pl zr na pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000246
DTS!CDBProviderInfos::EnumerateOLEDBSources+0x62:
22772918 3bc3 cmp eax,ebx
To find out what the Win32 error message description was, I used the !error extension.
0:008> !error 7e
Error code: (Win32) 0x7e (126) - The specified module could not be found.
OK. Now we know we are trying to load one module which couldn't be found, but how do we find out which module was it?
Well there are a couple of ways to determine that. You can either use a file monitoring tool like FileMon or ProcMon, or you can go the hard way, which works like this. :-)
When it was at the point where it was about to call CoCreateInstance for the root enumerator object, I set a breakpoint on kernel32!LoadLibraryExW (why on that one and not on LoadLibraryA, LoadLibraryW, or LoadLibraryExA? Simply because all of them end up calling LoadLibraryExW, so that one I know for sure sooner or later will be called), and when I hit that new breakpoint, I dumped its first parameter, which as per the documentation, it is a string:
0:011> kb40
ChildEBP RetAddr Args to Child
WARNING: Stack unwind information not available. Following frames may be wrong.
03f1da98 7752e0cd 03f1daf0 03f1dabc 03f1dac0 KERNEL32!LoadLibraryExW
03f1dac8 7752d550 03f1daf0 03f1ddc4 03f1dae8 ole32!CoGetTreatAsClass+0xec0
03f1dd14 7752d473 00000001 03f1ddc4 03f1dd44 ole32!CoGetTreatAsClass+0x343
03f1dd5c 7752d3d1 00000001 038b2a00 03f1dd84 ole32!CoGetTreatAsClass+0x266
03f1dd88 77516212 03f1ddc4 03f1e894 03f1e358 ole32!CoGetTreatAsClass+0x1c4
03f1ddfc 775160fe 77607150 03f1e358 03f1e894 ole32!CoGetClassObject+0x460
03f1de34 775162e4 03f1e358 03f1e894 03f1e358 ole32!CoGetClassObject+0x34c
03f1de54 77516290 77607154 03f1e358 03f1e894 ole32!CoGetClassObject+0x532
03f1de6c 7752ddf4 77607154 00000001 00000000 ole32!CoGetClassObject+0x4de
03f1de8c 7752ddab 7760714c 03f1e1b4 00000000 ole32!CoGetTreatAsClass+0xbe7
03f1dec4 77516337 7760714c 03f1e1b4 00000000 ole32!CoGetTreatAsClass+0xb9e
03f1deec 775160fe 7760714c 03f1e358 03f1e894 ole32!CoGetClassObject+0x585
03f1df24 77516118 03f1e358 03f1e894 003a0043 ole32!CoGetClassObject+0x34c
03f1e16c 775160fe 77607114 00000001 03f1e894 ole32!CoGetClassObject+0x366
03f1e1a4 77515f92 03f1e358 03f1e894 774eca10 ole32!CoGetClassObject+0x34c
03f1e950 77515e4b 7318c5a8 00000001 00000000 ole32!CoGetClassObject+0x1e0
03f1e97c 77515dcd 7318c5a8 00000001 00000000 ole32!CoGetClassObject+0x99
03f1e99c 731af454 7318c5a8 00000001 00000000 ole32!CoGetClassObject+0x1b
03f1e9fc 73165894 00000000 03f1f3e0 03f1ea50 oledb32!OpenDSLFile+0x21de2
03f1ea14 7752d110 06352168 00000000 03f1f3e0 oledb32!DllGetClassObject+0x27c8
03f1ea9c 7752cddf 77607150 00000000 03f1f058 ole32!CreateGenericComposite+0x2c05
03f1eadc 7752d02e 03f1f058 00000000 03f1f5a4 ole32!CreateGenericComposite+0x28d4
03f1eb30 7752cfa5 77607154 00000000 03f1f058 ole32!CreateGenericComposite+0x2b23
03f1eb50 7752ddf4 77607154 00000001 00000000 ole32!CreateGenericComposite+0x2a9a
03f1eb70 7752ddab 7760714c 03f1eeb4 00000000 ole32!CoGetTreatAsClass+0xbe7
03f1eba8 7752d08f 7760714c 03f1eeb4 00000000 ole32!CoGetTreatAsClass+0xb9e
03f1ebd0 7752cddf 7760714c 00000000 03f1f058 ole32!CreateGenericComposite+0x2b84
03f1ec10 7752cd7a 03f1f058 00000000 03f1f5a4 ole32!CreateGenericComposite+0x28d4
03f1ee60 7752cddf 77607114 00000000 03f1f058 ole32!CreateGenericComposite+0x286f
03f1eea0 7752cc24 03f1f058 00000000 03f1f5a4 ole32!CreateGenericComposite+0x28d4
03f1f650 774ffaba 226f1c3c 00000000 00000001 ole32!CreateGenericComposite+0x2719
03f1f678 774ffa89 226f1c3c 00000000 00000001 ole32!CoCreateInstanceEx+0x4f
03f1f69c 774ffaf7 226f1c3c 00000000 00000001 ole32!CoCreateInstanceEx+0x1e
03f1f6cc 22772918 226f1c3c 00000000 00000001 ole32!CoCreateInstance+0x34
03f1f80c 2275e894 03b28688 03f1cf14 03f1f83c DTS!CDBProviderInfos::EnumerateOLEDBSources+0x62
03f1f838 77e799dc 03b286f4 03901f50 02020202 DTS!CApplication::get_DBProviderInfos+0x69
03f1f854 77ef321a 2275e82b 03f1f868 00000002 RPCRT4!CheckVerificationTrailer+0x70
03f1fc58 77ef4ea5 00234b50 038e23f0 038d9c54 RPCRT4!NdrStubCall2+0x215
03f1fcb0 77132a57 00234b50 038d9c54 038e23f0 RPCRT4!NdrCStdStubBuffer2_Release+0x260
03f1fcd4 77600c31 00234b50 038d9c54 038e23f0 oleaut32!DllGetClassObject+0x182
03f1fd14 77600bdb 038d9c54 039053ec 038ba584 ole32!StgGetIFillLockBytesOnFile+0x10439
03f1fd5c 7750f237 038d9c54 0390d640 038fefa0 ole32!StgGetIFillLockBytesOnFile+0x103e3
03f1fe34 7750f15c 038e23f0 00000000 038fefa0 ole32!CoReleaseMarshalData+0x7dc
03f1fe50 77600b11 038d9c54 00000001 038fefa0 ole32!CoReleaseMarshalData+0x701
03f1fe80 776009bc 038d9c00 038e23f0 038fefa0 ole32!StgGetIFillLockBytesOnFile+0x10319
03f1ff54 77600df2 038d9c00 002341d8 00000000 ole32!StgGetIFillLockBytesOnFile+0x101c4
03f1ff80 7750fcb3 038d9c00 7c802540 00235e88 ole32!StgGetIFillLockBytesOnFile+0x105fa
03f1ff94 774fe3dc 038d9c00 b7b6b5b4 00235e88 ole32!DcomChannelSetHResult+0x5f4
03f1ffb4 7c80b683 00235e88 b7b6b5b4 bbbab9b8 ole32!StringFromGUID2+0x5da
03f1ffec 00000000 774fe429 00235e88 00000000 KERNEL32!GetModuleFileNameA+0x1b4
0:011> du 03f1daf0
03f1daf0 "C:\Program Files\Common Files\Sy"
03f1db30 "stem\msadc\msadce.dll"
Then, I run LoadLibraryExW until it completes and returns and this is what I see on its return. eax is 0, meaning that the function didn't return a handle to the file but NULL. And, based on the documentation again, that happens when the function fails.
.
.
.
eax=00000000 ebx=00000000 ecx=7c801bf6 edx=00000000 esi=77606068 edi=03f1daf0
eip=7752e1b1 esp=03f1da88 ebp=03f1da98 iopl=0 nv up ei pl nz ac pe nc
cs=001b ss=0023 ds=0023 es=0023 fs=003b gs=0000 efl=00000216
ole32!CoGetTreatAsClass+0xfa4:
7752e1b1 3bc3 cmp eax,ebx
So, if it failed, GetLastError should tell me the reason, or at least a hint.
0:011> !gle
LastErrorValue: (Win32) 0x7e (126) - The specified module could not be found.
OK, so msadce.dll is not where it's supposed to be?
Hummm... Well, since that component is distributed with MDAC, it's time to recommend using MDAC Component Checker to diagnose what else could be wrong with the installation of MDAC in that machine.
If you had the time and the guts to get through all this post, congratulations, you're my heroe! :-)