Debugging PE Explorer

From WineHQ Wiki
Jump to: navigation, search

PE Explorer from Heaventools is a program for examining the structure of Windows EXE and DLL files. As such it's sometimes useful for Wine debugging. While quite pricey, they have a free demo you can play with. The problem we're going to debug is that in the file open dialog, if you double click on a DLL it hangs. If you double click on an EXE file it works and the file opens, and if you click once on a DLL then hit the open button it also works. Only when you double click on a DLL does it hang - this is our first clue.

A hang like this is often caused by deadlock: one thread is waiting for another, which is in turn waiting for something that never happens (maybe it's waiting for the first thread, in which case we have a deadly embrace). So our first port of call is to find out what the threads are doing when the app has stopped. To do this, start up winedbg in another terminal and use the bt all command. This gives us the following output (some of it has been deleted to keep width low):

Wine-dbg>bt all

In 32 bit mode.
0xb7fe87a2: ret
Backtracing for thread 0xb in process 0x8 (C:\Program Files\PE Explorer\pexplorer.exe):
Backtrace:
=>1 0xb7fe87a2 (0x7e6cebd0)
  2 0x77ee0cd7 NTDLL_wait_for_multiple_objects(count=0x0, handles=0x0, flags=0x8, timeout=0x7e6ced10, signal_object=0x0)
  3 0x77edf2a6 usr1_handler+0x3a(__signal=0xa, __context=0x33)
  5 0x77ee0cd7 NTDLL_wait_for_multiple_objects+0x207(count=0x1, handles=0x7e6cb9c4, flags=0xc, timeout=0x7e6cb9bc, signal_object=0x0) 
  6 0x77ee0d9d NtWaitForMultipleObjects+0x4d(count=0x1, handles=0x7e6cb9c4, wait_all=0x0, alertable=0x0, timeout=0x7e6cb9bc)
  7 0x77baeaff WaitForMultipleObjectsEx+0xa3(count=0x1, handles=0x7e6cbaf8, wait_all=0x0, timeout=0x23, alertable=0x0)
  8 0x77baebee WaitForSingleObject+0x22(handle=0xc, timeout=0x23)
  9 0x77218d8c TIME_MMSysTimeThread(arg=0x7725ed40)
  10 0x77bb4bda THREAD_Start(ptr=0x77ccba40)
  11 0x77ee2437 start_thread+0x14b(info=0x77cb1e18)
  12 0xb7fae341 (0x7e6cc4c8)
  13 0xb7f44fee (0x00000000)

In 32 bit mode.
0xb7fe87a2: ret
Backtracing for thread 0xa in process 0x8 (C:\Program Files\PE Explorer\pexplorer.exe):
Backtrace:
  1 0xb7fe87a2 (0x7e7dfbd0)
  2 0x77ee0cd7 NTDLL_wait_for_multiple_objects(count=0x0, handles=0x0, flags=0x8, timeout=0x7e7dfd10, signal_object=0x0)
  3 0x77edf2a6 usr1_handler+0x3a(__signal=0xa, __context=0x33)
  5 0x77ee0cd7 NTDLL_wait_for_multiple_objects+0x207(count=0x1, handles=0x7e7ce728, flags=0x4, timeout=0x0, signal_object=0x0)
  6 0x77ee0d9d NtWaitForMultipleObjects+0x4d(count=0x1, handles=0x7e7ce728, wait_all=0x0, alertable=0x0, timeout=0x0)
  7 0x77baeaff WaitForMultipleObjectsEx+0xa3(count=0x1, handles=0x7e7ce9bc, wait_all=0x0, timeout=0xffffffff, alertable=0x0)
  8 0x7fedc9a3 X11DRV_MsgWaitForMultipleObjectsEx+0x4b(count=0x1, handles=0x7e7ce9bc, timeout=0xffffffff, mask=0xff, flags=0x0)
  9 0x77780958 send_inter_thread_message(res_ptr=0x7e7cea78)
  10 0x77781405 SendMessageTimeoutA+0x115(hwnd=0x100d4, msg=0x8fff, wparam=0x0, lparam=0x7f19aa10, flags=0x0, timeout=0xffffffff, res_ptr=0x7e7ceae0) 
  11 0x777814e1 SendMessageA+0x31(hwnd=0x100d4, msg=0x8fff, wparam=0x0, lparam=0x7f19aa10)
  12 0x00415b2c in pexplorer (+0x15b2c) (0x7e7ceb04)
  13 0x004a22b3 in pexplorer (+0xa22b3) (0x7e7ceb18)
  14 0x00415961 in pexplorer (+0x15961) (0x7e7ceb2c)
  15 0x004039b6 in pexplorer (+0x39b6) (0x7e7ceb40)
  16 0x77bb4bda THREAD_Start(ptr=0x77ca95b8)
  17 0x77ee2437 start_thread+0x14b(info=0x77ca98d0)
  18 0xb7fae341 (0x7e7cf4c8)
  19 0xb7f44fee (0x00000000)

In 32 bit mode.
0xb7fe87a2: ret
Backtracing for thread 0x9 in process 0x8 (C:\Program Files\PE Explorer\pexplorer.exe):
Backtrace:
  1 0xb7fe87a2 (0x77d9abd0)
  2 0x77ee0cd7 NTDLL_wait_for_multiple_objects(count=0x0, handles=0x0, flags=0x8, timeout=0x77d9ad10, signal_object=0x0)
  3 0x77edf2a6 usr1_handler+0x3a(__signal=0xa, __context=0x33)
  4 0xb7fb47c8 (0x7790b45c)
  5 0x77ee0cd7 NTDLL_wait_for_multiple_objects+0x207(count=0x1, handles=0x7790b5d0, flags=0x4, timeout=0x0, signal_object=0x0)
  6 0x77ee0d9d NtWaitForMultipleObjects+0x4d(count=0x1, handles=0x7790b5d0, wait_all=0x0, alertable=0x0, timeout=0x0)
  7 0x77baeaff WaitForMultipleObjectsEx+0xa3(count=0x1, handles=0x7790b704, wait_all=0x0, timeout=0xffffffff, alertable=0x0)
  8 0x77baebee WaitForSingleObject+0x22(handle=0x10, timeout=0xffffffff)
  9 0x77b9fa37 create_process(cmd_line=0x7790e3d4, env=0x0, cur_dir=0x0, psa=0x0, tsa=0x0, inherit=0x0, flags=0x400, startup=0x7790c654, info=0x7790c644, unixdir=0x77cd6808, res_start=0x0, res_end=0x0)
  10 0x77b9ffac CreateProcessW(app_name=0x0, cmd_line=0x7790e3d4, process_attr=0x0, thread_attr=0x0, inherit=0x0, flags=0x400, env=0x0, cur_dir=0x0, startup_info=0x7790c654, info=0x7790c644)
  11 0x77306642 SHELL_ExecuteW+0x96(lpCmd=0x7790e3d4, env=0x0, shWait=0x0, psei=0x7790d984, psei_out=0x7790e618)
  12 0x77308739 ShellExecuteExW32+0x949(sei=0x7790e618, execfunc=0x773065ac)
  13 0x77309374 ShellExecuteExA+0xbc(sei=0x7790e6a8)
  14 0x7730f575 ShellView_DoContextMenu(y=0x0, bDefault=0x1)
  15 0x773107ff ShellView_WndProc(hWnd=0x100f6, uMessage=0x4e, wParam=0x7d0, lParam=0x7790f1d4)
  16 0x777a36b3 WINPROC_wrapper+0x17
  17 0x777a3a64 WINPROC_CallWndProc+0x60(msg=0x4e, wParam=0x7d0, lParam=0x7790f1d4)
  18 0x777a87b5 CallWindowProcW+0x169(func=0x77800316, hwnd=0x100f6, msg=0x4e, wParam=0x7d0, lParam=0x7790f1d4)
  19 0x7777d2fe call_window_proc+0xb2(wparam=0x7d0, lparam=0x7790f1d4, unicode=0x1, same_thread=0x1)
  20 0x7777d6a2 SendMessageTimeoutW+0x136(hwnd=0x100f6, msg=0x4e, wparam=0x7d0, lparam=0x7790f1d4, flags=0x0, timeout=0xffffffff, res_ptr=0x7790f154) 
  21 0x7777d6e1 SendMessageW(hwnd=0x100f6, msg=0x4e, wparam=0x7d0, lparam=0x7790f1d4)
  22 0x77445eed notify_hdr(pnmh=0x7790f1d4)
  23 0x774528fa LISTVIEW_LButtonDblClk+0x11a(x=0x125, y=0x49)
  24 0x7745596e LISTVIEW_WindowProc+0xafe(hwnd=0x100f8, uMsg=0x203, wParam=0x1, lParam=0x490125)
  25 0x777a36b3 WINPROC_wrapper+0x17 in user32 (0x7790f35c)
  26 0x777a3a64 WINPROC_CallWndProc+0x60(msg=0x203, wParam=0x1, lParam=0x490125)
  27 0x777a86cf CallWindowProcW+0x83(func=0x777ff96c, hwnd=0x100f8, msg=0x203, wParam=0x1, lParam=0x490125)
  28 0x777821a2 DispatchMessageW+0xe2(msg=0x7790fa1c)
  29 0x7775a1d4 IsDialogMessageW+0xe0(hwndDlg=0x20028, msg=0x7790fa1c)
  30 0x7775a7c8 DIALOG_DoDialogBox(hwnd=0x20028, owner=0x10022)
  31 0x7775bc15 DialogBoxIndirectParamAorW+0x45(hInstance=0x77380000, template=0x773d4340, owner=0x10022, dlgProc=0x7739101c, param=0x7790faec, flags=0x2)
  32 0x7775bc7a DialogBoxIndirectParamA+0x26(hInstance=0x77380000, template=0x773d4340, owner=0x10022, dlgProc=0x7739101c, param=0x7790faec)
  33 0x7738c9b7 GetFileName95(fodInfos=0x7790faec)
  34 0x7738f0d0 GetFileDialog95A(ofn=0x7790fbdc, iDlgType=0x2)
  35 0x77392931 GetOpenFileNameA+0x39(ofn=0x7790fbdc)
  36 0x00497e0d in pexplorer (+0x97e0d) (0x7790fbc0)
  37 0x0049862c in pexplorer (+0x9862c) (0x7790fc50)
  38 0x00498a62 in pexplorer (+0x98a62) (0x7790fc60)
  39 0x00591461 in pexplorer (+0x191461) (0x7790fca8)
  40 0x0042444b in pexplorer (+0x2444b) (0x7790fccc)
  41 0x00424781 in pexplorer (+0x24781) (0x7790fd3c)
  42 0x00425ba7 in pexplorer (+0x25ba7) (0x7790fd9c)
  43 0x00425a1b in pexplorer (+0x25a1b) (0x7790fdcc)
  44 0x0042db32 in pexplorer (+0x2db32) (0x7790fde4)
  45 0x777a36b3 WINPROC_wrapper in user32 (0x7790fe08)
  46 0x777a3a64 WINPROC_CallWndProc(msg=0x202, wParam=0x0, lParam=0xa000a)
  47 0x777a8548 CallWindowProcA+0xe4(func=0x77800268, hwnd=0x100d2, msg=0x202, wParam=0x0, lParam=0xa000a)
  48 0x7778206e DispatchMessageA(msg=0x7790fec0)
  49 0x00433742 in pexplorer (+0x33742) (0x7790ff00)
  50 0x005a8b11 EntryPoint+0x13d in pexplorer (0x7790ff2c)
  51 0x77b9eaaf start_process+0xc3(arg=0x0)
  52 0xb7fd46c9 wine_switch_to_stack+0x11 in libwine.so.1 (0x00000000)

What we're looking at here is called a backtrace. It shows the nesting of each function call made on each threads stack. There are a few peculiarities here. The first one is that the main thread (the first one in the program) starts with two stack frames that are always the same, wine_switch_to_stack and start_process. Stack switching is a bit advanced for this tutorial, but it's only done for the first thread. So this is the one where typically most of the GUI related work will be done.

As you can see some frames have no function information, because they're inside the pexplorer file itself. We can ignore these. These frames don't tell us anything. Another peculiarity is the way the backtraces end:

  1 0xb7fe87a2 (0x77d9abd0)
  2 0x77ee0cd7 NTDLL_wait_for_multiple_objects(count=0x0, handles=0x0, flags=0x8, timeout=0x77d9ad10, signal_object=0x0)
  3 0x77edf2a6 usr1_handler+0x3a(__signal=0xa, __context=0x33)

These final 3 frames are the result of the way Wine and the Wine debugger works. In order to read where a thread is, it must be suspended, and suspending a thread adds these three frames. They aren't something the app is doing, they're the result of you looking at it.

Decoded, the program:

  • Starts up
  • Enters a standard Win32 message loop
  • We selected the File -> Open menu item, so it does some stuff, then calls GetFileDialog95A which pops up the file open dialog
  • The file dialog enters a message loop, which in turn then dispatches the double click
  • The double click is handled by the list view control (in comctl32), which in turn sends another message (a notification).
  • This is received by the ShellView object in its window procedure (wndproc).
  • For some reason control then passes to the context menu routine. This is strange, we didn't invoke a context menu, we double left clicked!
  • Even stranger, the context menu function then tries to execute something. It's a fair bet that it's trying to execute the DLL we double clicked which clearly isn't going to work
  • And indeed the thread then hangs whilst trying to execute the DLL (we can prove this by doing an +exec trace)

So there are two questions here. Firstly, why does trying to execute a DLL hang instead of returning an error code? Secondly (and this is the real bug), why is it trying to execute the DLL instead of just opening it anyway? If you think back to what a Windows context menu looks like in Explorer, "open" is usually the first and default item. So double clicking on a file in Explorer would normally try to open the file. It seems like instead of having PE Explorer open the file we're falling back to the default open action.

Let's look at the code for

  
 14 0x7730f575 ShellView_DoContextMenu(y=0x0, bDefault=0x1) [/wine/dlls/shell32/shlview.c:892] in shell32 (0x7790e754)
 15 0x773107ff ShellView_WndProc(hWnd=0x100f6, uMessage=0x4e, wParam=0x7d0, lParam=0x7790f1d4) [/wine/dlls/shell32/shlview.c:1284] in shell32 (0x7790eb30)

We see that in fact, line 1284 is not in ShellView_WndProc at all. It's actually a line inside ShellView_OnNotify, a static function. In this case, GCC detected that the function was used only once and automatically inlined it, effectively the OnNotify function "disappeared". This can lead to slightly confusing backtraces as the function name and actual line of code don't match up. If it is problematic, rebuild the affected DLL with -O0 which disables optimization. Here is the relevant snippet:

1 	  case LVN_ITEMACTIVATE:
2 	    TRACE("-- LVN_ITEMACTIVATE %p\n",This);
3 	    OnStateChange(This, CDBOSC_SELCHANGE);  /* the browser will get the IDataObject now */
4 	    ShellView_DoContextMenu(This, 0, 0, TRUE);
5 	    break;

Not much here, let's look at the ShellView_DoContextMenu function. We immediately see that it's large and has many branching points. Fortunately it has lots of tracing, so let's do a +shell trace to see what is going on:

trace:shell:ShellView_DoContextMenu -- get menu default command
trace:shell:ShellView_DoContextMenu -- uCommand=28930
trace:shell:ShellView_DoContextMenu -- dlg: OnDefaultCommand
trace:shell:OnDefaultCommand ICommDlgBrowser::OnDefaultCommand

Ah, so it's calling the OnDefaultCommand method of the ICommDlgBrowser object. This is a COM object, and we aren't immediately sure where it has come from. Grepping the tree for OnDefaultCommand reveals that it's hiding in dlls/commdlg/filedlgbrowser.c. The comment:

*  IShellBrowserImpl_ICommDlgBrowser_OnDefaultCommand
*
*   Called when a user double-clicks in the view or presses the ENTER key

is suggestive - we seem to have found the right place. This function is simple and there is a comment explaining what it should do: "If the selected object is not a folder, send an IDOK command to parent window". The branch we want looks like this:

 1         else
 2 	{
 3           /* Tell the dialog that the user selected a file */
 4 	  hRes = PostMessageA(This->hwndOwner, WM_COMMAND, IDOK, 0L);
 5 	}
 6 
 7         /* Free memory used by pidl */
 8         COMDLG32_SHFree((LPVOID)pidl);
 9 
10         return hRes;

We can immediately see this code is wrong. It's treating the return value of PostMessage as an HRESULT. From our knowledge of win32 (ask if you get stuck due to not knowing the API well enough!) we know that HRESULTs are used only in the COM parts of the system. PostMessage dates from the earliest days of Windows, before COM was invented. Looking at MSDN we see that it returns a BOOL, in other words, it returns zero for "fail" and non-zero for "success". But this is the opposite meaning to HRESULTs in which zero means success and non-zero is some error code! Looks like we found our bug. We're inverting the success of this function (which may or may not return TRUE, we don't know).

So we try it and surprise surprise, changing the code to read like this:

 1         else
 2 	{
 3           /* Tell the dialog that the user selected a file */
 4 	  PostMessageA(This->hwndOwner, WM_COMMAND, IDOK, 0L);
 5           hRes = S_OK;
 6 	}
 7 
 8         /* Free memory used by pidl */
 9         COMDLG32_SHFree((LPVOID)pidl);
10 
11         return hRes;

.... fixes the bug.