Just Let It Flow

May 7, 2011

DLL – Demystifying Loader Lapses

Filed under: Code,Windows — adeyblue @ 12:17 am
  1. Introduction
  2. Setting up
  3. The Debug Output
  4. Running Though an Example
  5. Wrap-up
  6. Notes

Introduction

DLL hell isn’t just the name given to managing monstrous dependency chains. It’s also the name given to the phenomenon of pulling your hair out because LoadLibrary is returning NULL or because your dotNet app is throwing lots of System.DllNotFoundExceptions. The usual statement Windows gives as witness to these crimes is ‘Module not found’ as if it were some blind referee or umpire giving a call against the local sports team, while you swear blind at the injustice and can point at the exact file you wanted in an Explorer window.

On the surface of things it may seem like a hard luck story. Sure you can go hook this and that in effort to figure out why appending the filename to the dll search path resulted in failure, but like Bud Selig calling the All-Star game a tie, Windows levels the playing field by housing a certain tool you can leverage. And without having to write any more code in investigative anger or download anything too.

Setting up

The tool to enable is one of the plethora controlled by the ever useful GlobalFlags constant I’ve mentioned before. This time, instead of the leak checking, the ShowSnaps option is the desired one. This value instructs Windows to output a trace of the various dll related functionality.

While you can set this up in various ways, probably the simplest way to enable this tracing is to add a key to the Image File Execution Options part of the registry as follows:

  1. Open regedit to HKEY_LOCAL_MACHINE\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Image File Execution Options
  2. Add a new key that has the same name as your program, including the extension
  3. Under that key, add a new DWORD value named ‘GlobalFlag’ (without the quotes) with a value of 2 [1]

Or you can use the batch file here.

Then, if you’re using Visual Studio:

  1. Start the project with Debugging (F5)
  2. The debug spew will be in the Output window or Immediate window depending on options

… Or WinDBG:

  1. Select ‘Open Executable’ from the File menu
  2. F5 or type ‘g’ (without quotes) to continue

…Otherwise:
Well, I don’t use anything else but I’m sure any debugger will display the output. Note that DebugView will *not* display it. If your debugger won’t, you can compile the program here and redirect the output as desired.

The Debug Output

After you run it, the first thing you’ll notice is the sheer volume of output. The second panel below is the output for the simple program in the first.

#include <windows.h>
#include <stdio.h>
int main(int argc, char** argv)
{
    HMODULE hMod = LoadLibraryW(L"sdfghj.dll"); // non-existant
    if(!hMod)
    {
        puts("Failed to load dll");
    }
    return 0;
}


(Sorry about the iframe, WordPress won’t display the entry if I embed it in the entry)

OK, now you’ve got your 341KB of tracing, where the heck do you start? Thankfully, ‘at the start’ is not the answer.

If you don’t know the exact name of the dll that’s failing to load, the immediate thing to do is grep or search the trace for any return status starting with ‘0xc’. This prefix indicates NTSTATUS values that have a severity of ‘error’, failing to load a dll is included in this bracket. When you find one, they can be decode into readable statuses by looking for their value in ntstatus.h in the SDK, googling, or ‘winerror -s ‘ using that tool in the WDK. The format of the output is thus:

Process ID : ThreadID @ Clock Ticks - Message

Message almost always include the function name as the first thing, those always start with Ldr. These are likely undocumented functions but are named such that you can have a pretty good idea what they’re doing. Messages are also displayed in stack format. You’ll see several messages in a row for entry into various functions before messages for their return in reverse order. Yep, that’d be a stack alright.

Running Through an Example

Names feature very prominently in the info dump. If you know the dll name that’s not loading you can zero in much quicker on the relevant parts. If we run through the spew above with the short program example, the bits of it that relate to the loading of our non existant dll are:

0f60:0e10 @ 04964295 - LdrLoadDll - ENTER: DLL name: sdfghj.dll DLL path: f:\Dev-Cpp\Projects\Test\Adjustor\x64\Release;C:\Windows\system32;C:\Windows\system;C:\Windows;.;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\Subversion\bin;F:\Dev-Cpp\Projects;G:\Microsoft Visual Studio 9.0\VC\bin\amd64
0f60:0e10 @ 04964295 - LdrpLoadDll - ENTER: DLL name: sdfghj.dll DLL path: f:\Dev-Cpp\Projects\Test\Adjustor\x64\Release;C:\Windows\system32;C:\Windows\system;C:\Windows;.;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\Subversion\bin;F:\Dev-Cpp\Projects;G:\Microsoft Visual Studio 9.0\VC\bin\amd64
0f60:0e10 @ 04964295 - LdrpLoadDll - INFO: Loading DLL sdfghj.dll from path f:\Dev-Cpp\Projects\Test\Adjustor\x64\Release;C:\Windows\system32;C:\Windows\system;C:\Windows;.;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\Subversion\bin;F:\Dev-Cpp\Projects;G:\Microsoft Visual Studio 9.0\VC\bin\amd64
0f60:0e10 @ 04964295 - LdrpFindOrMapDll - ENTER: DLL name: sdfghj.dll DLL path: f:\Dev-Cpp\Projects\Test\Adjustor\x64\Release;C:\Windows\system32;C:\Windows\system;C:\Windows;.;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\Subversion\bin;F:\Dev-Cpp\Projects;G:\Microsoft Visual Studio 9.0\VC\bin\amd64
0f60:0e10 @ 04964295 - LdrpFindKnownDll - ENTER: DLL name: sdfghj.dll
0f60:0e10 @ 04964295 - LdrpFindKnownDll - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpSearchPath - ENTER: DLL name: sdfghj.dll DLL path: f:\Dev-Cpp\Projects\Test\Adjustor\x64\Release;C:\Windows\system32;C:\Windows\system;C:\Windows;.;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\Subversion\bin;F:\Dev-Cpp\Projects;G:\Microsoft Visual Studio 9.0\VC\bin\amd64
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: f:\Dev-Cpp\Projects\Test\Adjustor\x64\Release\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\system32\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\system\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: .\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\system32\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\System32\Wbem\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\System32\WindowsPowerShell\v1.0\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Program Files (x86)\Subversion\bin\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: F:\Dev-Cpp\Projects\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: G:\Microsoft Visual Studio 9.0\VC\bin\amd64\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpSearchPath - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpFindOrMapDll - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpLoadDll - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrLoadDll - RETURN: Status: 0xc0000135

The first notification is upon entering LdrLoadDll, the ntdll function behind LoadLibrary. Breaking down the message we can see in order:

0f60:0e10 - The Process id and Thread id in hex
04964295 - when this happened, in ticks
LdrLoadDll - Where it happened
DLL name: sdfghj.dll - The dll name the function is trying to load, and then the contents of the dll search path
DLL path: f:\Dev-Cpp\Projects\Test\Adjustor\x64\Release;C:\Windows\system32;C:\Windows\system;C:\Windows;.;C:\Windows\system32;C:\Windows;C:\Windows\System32\Wbem;C:\Windows\System32\WindowsPowerShell\v1.0\;C:\Program Files (x86)\Subversion\bin;F:\Dev-Cpp\Projects;G:\Microsoft Visual Studio 9.0\VC\bin\amd64

It’s an inauspicious start that gives general information we could have gotten ourselves. But it’s nice to know we didn’t have to. It’s good diagnostic info too, in case somebody changed the dll search paths inbetween different load attempts.

This info dump continues on the same lines as LdrLoadDll calls a few subfunctions. The first proper try to resolve and load the dll name comes after those:

0f60:0e10 @ 04964295 - LdrpFindKnownDll - ENTER: DLL name: sdfghj.dll
0f60:0e10 @ 04964295 - LdrpFindKnownDll - RETURN: Status: 0xc0000135

Here’s where that NTSTATUS lookup becomes handy. 0xc0000135 is STATUS_DLL_NOT_FOUND. Combined with the function which returned the status, it’s safe to say at the time of calling sdfghj.dll wasn’t a known dll. First port of call down, the loader moves on into LdrpSearchPath. We don’t need to be geniuses to figure out what its gonna do here:

0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: f:\Dev-Cpp\Projects\Test\Adjustor\x64\Release\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\system32\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\system\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: .\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\system32\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\System32\Wbem\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Windows\System32\WindowsPowerShell\v1.0\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: C:\Program Files (x86)\Subversion\bin\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: F:\Dev-Cpp\Projects\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpResolveFileName - ENTER: DLL name: G:\Microsoft Visual Studio 9.0\VC\bin\amd64\sdfghj.dll
0f60:0e10 @ 04964295 - LdrpResolveFileName - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpSearchPath - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpFindOrMapDll - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrpLoadDll - RETURN: Status: 0xc0000135
0f60:0e10 @ 04964295 - LdrLoadDll - RETURN: Status: 0xc0000135

This now shows what the problem is. LdrpResolveFileName tries it’s darnedest to load the dll, looking almost everywhere except the kitchen sink and each time our friend STATUS_DLL_NOT_FOUND was returned. As the status bubbles up back through LdrLoadDll, Windows gives up and returns NULL to LoadLibrary. Even more invaluably, the dump shows the exact paths tried. This may not mean much in this example but when dll redirection and activation contexts get involved, knowing exactly what was searched for helps that little bit more.

You may have noticed that there’s a lot more logged than just dll loads though. This debug output can help when GetProcAddress fails, when module hints and bindings are incorrect (does anybody do that anyway?), when your actual dll is perfectly fine but its dependencies aren’t, viewing Side-by-Side and .local redirections, and more.

Conclusion

34 lines out of almost 2000 isn’t a great percentage of relevant information hits, heck it’s probably the same as the White Sox’s win percentage, but like most tools, at some point and in real programs you’ll be glad that 0.17% exists. It won’t tell you in plain English, but this extra help detailing the exact steps Windows took to try and load the dll should swing the fight between problem and problem solver further in your direction.

The good news is that since this functionality is built into the base operating system, it works with any program which creates a process. So VBS/JS (wscript.exe/cscript.exe), Office add-ins, Java (java.exe), .Net, IE/Firefox add-ins, and pretty much everything else can be logged and investigated using this technique.


[1]: You can also enable this debug spew and the other GlobalFlag constants by adding a IMAGE_LOAD_CONFIG_DIRECTORY structure to your program and setting the GlobalFlagsSet member to the desired value.

[2]: ShowSnaps.cmd batch file

@echo off
if "%1" EQU "" (
  call :ShowUsage
  goto :eof
)
 
set progName=%~nx1
 
if NOT "%3" EQU "1" (
  set regPath=HKLM\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Image File Execution Options
) else (
  set regPath=HKLM\Wow6432Node\SOFTWARE\Microsoft\Windows NT\CurrentVersion\Image File Execution Options
)
 
set progRegPath="%regPath%\%progName%"
 
if "%2" EQU "on" (
  set operation=add
  set command=reg %operation% %progRegPath% /v GlobalFlag /t REG_DWORD /d 0x2 
) else if "%2" EQU "off" (
  set operation=delete
  set command=reg %operation% %progRegPath% /v GlobalFlag /f
) else (
  call :ShowUsage
  goto :eof
)
 
%command%
 
goto :eof
 
:ShowUsage
@echo Usage: ShowSnaps ^<program name^> ^<setting (on^|off)^> ^<is32BitProgOnWin64 (1^|0)^>
@echo Where the words in brackets are the valid options for that argument

[3]:DbgOutDump for poor debuggers

#define WIN32_LEAN_AND_MEAN
#include <windows.h>
#include <cstdio>
#include <vector>
#include <string>
 
// run as
// DbgOutDump C:\Path\To\Program.exe any other "args you need"
 
int __cdecl wmain(int argc, wchar_t** argv)
{
    PROCESS_INFORMATION pi = {0};
    STARTUPINFO si  = {sizeof(si), 0};
    si.dwFlags = STARTF_USESHOWWINDOW;
    si.wShowWindow = SW_SHOW;
    std::wstring cmdLine;
    for(int i = 1; i < argc; ++i)
    {
        cmdLine += L"\"";
        cmdLine += argv[i];
        cmdLine += L"\" ";
    }
    cmdLine.push_back(0);
    if(CreateProcess(NULL, &cmdLine[0], NULL, NULL, FALSE, DEBUG_PROCESS | DEBUG_ONLY_THIS_PROCESS, NULL, NULL, &si, &pi))
    {
        CloseHandle(pi.hThread);
        DEBUG_EVENT ev = {0};
        std::vector<BYTE> bytes;
        BOOL bExit = FALSE;
        while((!bExit) && (WaitForDebugEvent(&ev, INFINITE)))
        {
            switch(ev.dwDebugEventCode)
            {
                case OUTPUT_DEBUG_STRING_EVENT:
                {
                    const OUTPUT_DEBUG_STRING_INFO& dbgInf = ev.u.DebugString;
                    bytes.resize(dbgInf.nDebugStringLength * (dbgInf.fUnicode + 1));
                    ReadProcessMemory(pi.hProcess, dbgInf.lpDebugStringData, &bytes[0], bytes.size(), NULL);
                    printf(dbgInf.fUnicode ? "%*S\n" : "%*s\n", dbgInf.nDebugStringLength - 1, &bytes[0]);
                }
                break;
                case EXIT_PROCESS_DEBUG_EVENT:
                {
                    bExit = TRUE;
                }
                break;
            }
            ContinueDebugEvent(ev.dwProcessId, ev.dwThreadId, DBG_CONTINUE);
        }
        CloseHandle(pi.hProcess);
    }
    return 0;
}

Powered by WordPress