Reading Debug Trace Examples

From Wine-Wiki.org
Jump to: navigation, search

Contents

Reading Suspicious Traces

Identifying what went wrong can be almost an art, so here are some examples. Also dont forget the official wiki page: http://wiki.winehq.org/LookupUuidTable

This page has grown too big, we are in the process of splitting it up.

Reading a backtrace

A user asked; When it crashes, how does one interpret the crash details? Generic information please - not specific. Mostly the documents do not exist and when I do find something it usually assumes a lot of existing knowledge.

V. Povirk: What you're asking for is impossible. You really need a lot of existing knowledge. No royal road and such. I'm going to try anyway[..]

Usually the only useful information you can get from crash details is:

  1. What was the most immediate bad thing that happened?
  2. What function tried to do the bad thing?
  3. What functions called the function that tried to do the bad thing?

Usually, the error is an "unhandled page fault" on attempting to read, write, or execute something. "Page fault" means the program is trying to do something that does not make sense given its current memory layout. For example, the address 0x00000000 usually is not assigned any meaning. If a program tries to call a function at that address, it will cause a page fault executing 0x00000000. The program has a chance to recover from things like this; if it doesn't, it crashes.

The "Backtrace" is a list of functions that are currently being executed.

If any involved functions are in a Wine dll, and you have debugging symbols, it should give you an exact line in the source code and the values of variables that the time of the crash. If you can't get this information (either you don't have debugging symbols or all the involved functions are in a native windows exe or dll), the backtrace is probably useless.

If you see the RaiseException function at the top of the trace, that function isn't broken. It means either there's an unimplemented function (in which case the log will also say "Call to unimplemented function library.NameOfFunction"), or a program/library has deliberately raised an exception (which, if not handled, causes a crash).

If you have to gather more information about a crash, a good step is often to get a +seh,+relay log and find the trace:seh:raise_exception lines immediately before the crash. Often what happens just before that is related.

Often crashes happen because something very bad happened earlier and now something is wrong with the program state (e.g. some variable should never be NULL, but now it is for some reason). The crash details only give you a snapshot in time; they cannot tell you how the program got into that state. If you can't infer the reason from looking at the code, you need to gather more information. [..] Windows API documentation helps a lot. MSDN (the Win32 and COM Development section) is good for looking up specific functions or areas. If you're really serious, you might even want to pick up a book about programming for Windows in C.

He then examined an example submitted:

xrandr:X11DRV_XRandR_SetCurrentMode Cannot change screen BPP from 32 to 16

X11DRV_XRandR_SetCurrentMode is the name of the function that printed this information. You can find the source code for that function by doing an identifier search for X11DRV_XRandR_SetCurrentMode at http://source.winehq.org/.

From there you can see the line of code in context. Of course [in this case], the context probably won't give you any insight into what it actually means, namely that because of X limitations, Wine can't actually change the screen depth and lies to the application instead. Usually this is fine; in fact I've never heard of it causing a problem. We really have no business printing that scary useless thing IMO. It should never be necessary to document these things. If, as in this case, there is a common message that is basically never useful, it should be probably be changed to a WARN or TRACE. If there is a message that does commonly mean the same thing for users, that information should be in the message itself, not buried in documentation. For messages that rarely occur or are only meaningful to programmers, the source code is enough.

Trouble with backtraces

Winehq Bugzilla entry 19612 noted a problem when: a backtrace varies for some reason

Sometimes:

Backtrace:
=>0 0x00000010 (0x0032ea9c)
  1 0x7e3ca9c8 GdipGetImageWidth+0x109(image=0x188a40, width=0x32eafc)
[/home/test/wine-git/dlls/gdiplus/image.c:971] in gdiplus (0x0032eaec)

Sometimes:

Backtrace:
=>0 0x22010203 (0x0032f85c)
  1 0x0041ba12 in extendscript toolkit (+0x1ba12) (0x0032f8a4)

V. Povirk: That probably means none of the traces are useful, and the important failure happens earlier.

General Information

0009:Ret  ws2_32.gethostbyname() retval=00000000 ret=004725f1
0009:trace:seh:EXC_RtlRaiseException code=c0000005 flags=0 addr=0x4725f1

M.Hearn: Retval is what the functions result was. Ret is the code address that the function was called from. You can normally ignore it but it's useful for disassembly.

M. Hearn: a NULL return [ws2_32.gethostname() retval=00000000] means an error occurred.


warn:ntdll:NtCreateFile L"\\??\\C:\\Program Files\\origin6.0\\UNTITLED.OPJ" not found (c0000034)

A user noted the L"\\??\\" looks odd..

A. Julliard: The \??\ is the NT prefix, that's normal.Wine Archive


Reading Video Traces

This now has it's own page. Listed here are some of the entries..

OLE

err:ole:CoGetClassObject class {1968106d-f3b5-44cf-890e-116fcb9ecef1} not registered

N. Sivov apr 09: It's something Vista-only related, so ignore it.Winehq Bugzilla entry 18150

err:ole:CoGetClassObject class {00000100-0000-0010-8000-00aa006d2ea4} not registered

D. Timoshkov [aut 08 bug14858] try 'winetricks mdac25.

wine ESales.exe 
err:ole:CoGetClassObject class {00000514-0000-0010-8000-00aa006d2ea4} not registered
err:ole:CoGetClassObject class {00000514-0000-0010-8000-00aa006d2ea4} not registered
err:ole:create_server class {00000514-0000-0010-8000-00aa006d2ea4} not registered
err:ole:CoGetClassObject no class object {00000514-0000-0010-8000-00aa006d2ea4} could be created for context 0x7 
Error Code = 80040154 Code meaning = Unknown error 0x80040154 Source = (null) Description = (null) 
Open dataSource error wuhaibo@wuhaibo-desktop:~/.wine/drive_c/Program Files/PASOFTS/ESales/bin$

Vitamin [Nov 08] Looks like ADO/MDAC: Code: w get http://www.kegel.com/wine/winetricks sh ./winetrics mdac25


fixme:ole:OLEPictureImpl_FindConnectionPoint no connection point for{33ad4ed2-6699-11cf-b70c-00aa0060d393}

A poster asked what this was: Anyone know?

R. Shearman: I'm not so sure. I think it is an internal VB interface as it seems to only happen with VB apps. I am curious as to its purpose, though I don't think it is a source of any errors. In fact, I should write a test for the Wine test suite and silence the fixme for that particular IID. wine archive

err:ole:CoGetClassObject class {62a1cafb-1940-798f-6859-a5623c7ba562} not registered 
err:ole:CoGetClassObject no class object {62a1cafb-1940-798f-6859-a5623c7ba562} 
could be created for for context 0x1 
fixme:ole:CoCreateInstance no classfactory created for CLSID {62a1cafb-1940-798f-6859-a5623c7ba562},
hres is 0x80040154
err:ole:get_unmarshaler_from_stream Failed to create marshal, 0x80040154
err:ole:_unmarshal_interface Unmarshalling interface {b3b13603-a675-11d2-9b95-00104b71eb3f} failed with 80040154

R. Shearman [May 06]: Can you see what is under HKCR\Interface\{b3b13603-a675-11d2-9b95-00104b71eb3f}\ProxyStubClsid32 in your registry? He then posted another section of the trace where the bug was hiding..

trace:ole:_marshal_interface ...{b3b13603-a675-11d2-9b95-00104b71eb3f}...
trace:ole:CoMarshalInterface (0x798f1940, {b3b13603-a675-11d2-9b95-00104b71eb3f}, 0x79e309ec, 0, (nil),
MSHLFLAGS_NORMAL) trace:ole:IiFTMUnknown_fnQueryInterface
trace:ole:FTMarshalImpl_AddRef fixme:ole:FTMarshalImpl_GetUnmarshalClass (), stub!

Actually, this is the bug. This function doesn't fill in the CLSID properly. Also, UnmarshalInterface is unimplemented for the free-threaded marshaler. The free-threaded marshaler could really do with having some test-cases in the test suite. wine archive


wine debug then gives: ...... fixme:variant:VarBstrFromDec semi-stub fixme:variant:VarBstrFromDec semi-stub fixme:variant:VarBstrFromDec semi-stub fixme:ole:MSFT_ReadValue BSTR length = -1? fixme:ole:MSFT_ReadValue BSTR length = -1? fixme:ole:ITypeLibComp_fnBind (L"CHR", 107e4b, 0x3, 0x4068ac60, 0x4068ac54, 0x4068ac6c): stub fixme:ole:ITypeLibComp_fnBind (L"CHR", 107e4b, 0x3, 0x4068ac60, 0x4068ac54, 0x4068ac6c): stub fixme:ole:ITypeLibComp_fnBind (L"CHR", 107e4b, 0x3, 0x4068ac60, 0x4068ac54, 0x4068ac6c): stub</pre>


R. Shearman: The function ITypeLibComp_fnBind is unimplemented. I've looked at this function before, but I haven't found enough documentation to implement it properly.Wine Archive Link

./../../tools/runtest -q -P wine -M oleaut32.dll -T ../../.. -p 
oleaut32_test.exe.so typelib.c && touch typelib.ok
err:ole:TLB_ReadTypeLib Loading of typelib L"olepro32.dll" failed with error 1812
typelib.c:39: Test failed: Could not load type library
fixme:ole:RegisterTypeLib Registering non-oleautomation interface!
fixme:ole:RegisterTypeLib Registering non-oleautomation interface!

S. Shemesh: Copying olepro32.dll from a windows solves this one. Wine Archive Link


Unregistered Dll

fixme:ole:CoCreateInstance no classfactory created for CLSID {a65b8071-3bfe-4213-9a5b-491da4461ca7}, hres is 0x80040154
                      ^^^^^^^^^^

A. Mohr: why don't you regsvr32 that DLL (DxDiagProvider).[..] (darn, we need a *useful* error msg for that *frequent* error) [...] IMHO it should output something like:

err:ole:CoGetClassObject class {a65b8071-3bfe-4213-9a5b-491da4461ca7}not registered
- try running regsvr32 on the container DLL of this CLSID value!

which: - mentions regsvr32 - mentions that an unregistered DLL is involved And thus is an actually useful error message (to clueless endusers, that is).


R. Shearman: This is fixed by patch OLE #81a (Part 1) It will then output:

err:ole:CoGetClassObject class {a65b8071-3bfe-4213-9a5b-491da4461ca7} not registered

If they have enough expertise to know that the CLSID is that of a DXDiag object then I think they will know that they can register it by using regsvr32 and I don't think this is the right place for documenting the possible reasons for the error. However, this particular problem was that the user didn't re-register all of the DLLs after upgrading. Maybe we should have something in the docs that tells the user to do this after upgrading to a new version of Wine or have it done automatically somehow.

rpcrt

cstub.c:519: Test failed: QueryInterfacevtbl 1 not updated 7EA7F07E

Winehq Bugzilla entry 21479 - +relay changes the entry point addresses, that's expected. [Jan 10]

DAO

A user reported a database stopping from version 1.1.29. Vitamin: Set "oledb32" to native. Wine-1.1.29 has aa new implementation for this dll which is not complete. [(and install mdac using winetricks)]

Reading Com Port traces

000d:trace:comm:dump_dcb bytesize=8 baudrate=2400 fParity=0 Parity=0 stopbits=1

D. Riekenberg [May 2007 wine user] The App is using 2400 Baud here.

D. Moriarty: You can use setserial to set up comm 2 (or another box), link comm 1 to comm 2 (On 9 pin leads 2 - 3; 3 - 2; 5 - 5) will usually do it if you turn off hardware flow control, or get a 'laplink' lead. Make sure you have software flow control, and a parity bit. Then 'd d if=/dev/ttyS<integer> of=myfile bs=1 count=10000 will get you 10K of what it says.


=>1 0xb7d6934c memcpy+0x1c() in libc.so.6 (0x0033db78)
  2 0x7bc53348 call_entry_point+0x20() in ntdll (0x0033db94) 
  3 0x7bc53d0c SNOOP_Return+0x9a4() in ntdll (0x0033dc04) 
  4 0x7e96d431 in oleaut32 (+0xd431) (0x7b8294bc) 
  5 0xfde80201 (0x02976854) 
  6 0x00000000 (0x00000000) 0xb7d6934c memcpy+0x1c in libc.so.6: repe movsl (%esi),%es%edi)

Vitamin [jul08] Snoop channel is unreliable and can cause crashes like that. So don't spend time trying to chase something that's not your problem.

wine client error:132: pipe: Too many open files wine client error:

Vitamin [wineuser aug 08] What does: ulimit -n say? Can you increase it and see what happens?

the user cautiously reported: It says 1024 Will check man page and try to increase whatever that is. [...] This experiment isn't currently being run on a work computer, it's being done on my personal laptop.

CLSID

You can list some of the Universal Unique Identifiers here, along with info that might help wine users. According to wikipedia CLSID is a class identifier; (Stored in the registry at HKEY_CLASSES_ROOT\CLSID)

Retrieving the COM class factory for component with CLSID {72C24DD5-D70A-438B-8A42-9842B88AFB8} - failed due to the following error: 800004002, at bt.a(String A_0, String A_1). 

A English May 08 wine user, pointed to using winetricks to install a missing component

err:ole:CoGetClassObject class {00000507-0000-0010-8000-00aa006d2ea4} not registered err:ole:create_server class {00000507-0000-0010-8000-00aa006d2ea4} not registered

L. Lenders Jun 08 bug 13996: If you google for that uuid (or look in windows registry) you see it belongs to msado15.dll. Try http://kegel.com/wine/winetricks , winetricks art2kmin

Further Reading

Printing

fixme:commdlg:PRINTDLG_OpenDefaultPrinter Could not open printer EPSONStylusC42?!
No such dialog is displayed

J.Lang: This is a red herring. It's not trying to display a dialog, it's telling you that the default printer specified in win.ini couldn't be opened. It's not a bug, but a configuration error.


fixme:commdlg:PRINTDLG_OpenDefaultPrinter Could not open printer styluscolor600?!
err:psdrv:PSDRV_FindPrinterInfo OpenPrinterA failed with code 1801

Wineuser: Adding some entries in my wine registry (using regedit) and the win.ini in the fake_windows directory, like described in this tutorial: http://www.la-sorciere.de/Wine-HOWTO/wineprintconfig.html, in the part "Printing with the Internal Postscript Driver in Wine". Seems the tutorial isn't really up to date because I had to use [ppd] "generic" = "/usr/local/share/wine/generic.ppd" instead of [psdrv] ..., and I didn't need the entries for the afm-files.


Further Reading



fixme:psdrv:PSDRV_ExtEscape GETSETPRINTORIENT not implemented (data (nil))!
fixme:commdlg:PRINTDLG_SetUpPrinterListComboA Can't find 'tp0' in printer list so trying to find default
fixme:commdlg:PRINTDLG_SetUpPrinterListComboA Can't find default printer in printer list
fixme:commdlg:PRINTDLG_UpdatePrintDlgA No lpdm ptr?
fixme:commdlg:PRINTDLG_WMCommandA Update printdlg was not successful!
fixme:commdlg:PRINTDLG_UpdatePrintDlgA No lpdm ptr?
              ^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^
fixme:commdlg:PRINTDLG_WMCommandA Update printdlg was not successful!

D. Riekenburg: [Sept05] DevMode - Support is incomplete in Wine yet. I'm working on this, but that will take a while (there a many unimplemented things in the Printing-Part of Wine). Wine Archive

XML

fixme:msxml:bsc_QueryInterface interface {6d5140c1-7436-11ce-8034-00aa006009fa} not implemented
fixme:msxml:bsc_QueryInterface interface {79eac9e4-baf9-11ce-8c82-00aa004ba90b} not implemented

Vitamin wineuser aug 08: Install msxml:[type in a terminal]

cd ~
w get http://www.kegel.com/wine/winetricks 
sh ./winetricks msxml3

msclrhd Nov 08 referring to a previous post: it cannot create an instance of the msxml4 object (that is what 88d969c1-f192-11d4-a65f-0040963251e5 is referring to). You can install this by running

sh winetricks msxml4

Fonts

 err:font:ReadFontDir Can't open directory
 "/usr/local/bin/../lib/../share/wine/fonts/"

A user noticed this error when when fontforge isn't installed.

D. Timoshkov: Missing fontforge means that you don't have Wine builtin fonts which leads to the above problems. The solution obviously is to install fontforge or use a binary Wine package instead.

The user noticed the path above.:It's relative to '/usr/local/bin', ok - but why the double descend into the parent directory? The "../lib" seems completely redundant with the "../share" coming right after it.

D. Timoshkov: That's a feature of a now fully relocatable Wine installation. wine archive

T. Spear clarified: What it does is check /usr/local/bin/wine/fonts and when it doesn't find the fonts there, it backs up and moves to /usr/local/lib/wine/fonts, when it doesn't find them there, it backs up again and moves to /usr/local/share/wine/fonts. When it doesn't find them there either, it fails.. That is why they say it is fully relocatable.. (AFAIK) You can move the entire install out of the bindir and wine won't die...

The user noted: [you tell about this] ERR about it at run-time. You do not tell in your error message what the ground cause for the ERR is.

M.McCormack: Some patches have been applied to Wine that should improve the situation. We now only warn at configure time.

trace:font:WineEngGetFontData font=0x405757d8, table=70616d63, offset=00000000, buf=0x4374720c, cbData=0
trace:font:WineEngGetFontData font=0x405757d8, table=20747663, offset=00000000, buf=0x4374859c, cbData=ffffec70

R. Klazes: cbData 0xffffec70looks wrong, it is supposed to be the length of buf (0x4374859c)[...] we get an fault accessing at an offset of 0xb0a64 of buf: First chance exception: page fault on write access to 0x437f9000 in 32-bit

The question is where this 0xffffec70 comes from. If you run with WINEDEBUG=+relay,+font can you spot this value anywhere? At least post 200 lines of this log directly preceding this line.

It turned out to be from a gdi call: R. Klazes: Here is an explanation [and a patch] The programs does:

  1. call GetFontData with buffer size zero, to return the required buffer size;
  2. do that for a number of font tables, adding the required sizes;;
  3. allocate a buffer large enough to store the data from all the GetFontData calls;
  4. then filling the buffer with GetFontData calls, using the return value of the call to calculate the remaining free size.
  5. because Wine's GetFontData is not returning the actual size of the data put in the buffer, but the buffer size it self. The pointer to the buffer data is now pointing beyond the boundary. It does not go wrong immediately because size is zero now, but at the following GetFontData call the page fault is inevitable. wine archive
trace:font:WineEngGetFontData font=7ff405d8, table=46454447,offset=00000000, buf=0, cbData=0
trace:font:WineEngGetFontData Can't find table 47444546.

A developer questioned [May 06]: Should freetype be able to find these these tables?

H.Davies: FreeType can load any TT table. Most likely the font in question doesn't contain these tables. wine archive


fixme:font:load_VDMX Failed to retrieve vTable

H. Davies: [Dec 05] It just means that the font doesn't have a VDMX table. The reason there's a fixme there is that I'm not sure whether we correctly scale the font in that case.

A. Mohr: This FIXME is quite confusing and should be fixed, since it's NOT at all about the "common" vTable term, but instead a VDMX font-related table AFAICS.

Use winedbg, set a breakpoint on load_VDMX(), step through it until the 2nd WineEngGetFontData() (that one is failing!), then step through it until you know what exactly fails. Maybe even a simple freetype upgrade might resolve the issue? (in that case we'd need to know which freetype version is problematic) wine archive

Networking

MsgBox

A developer reported [May 06] that he tried: +msgbox to find a trace for the message box that's created, but that didn't seem to work for some reason.

M. Hearn: It might be generated by the app itself ... if you're sure it's a win32 message box look at the relay trace for MessageBox wine archive

HTML

$ wine iexplore
fixme:shdocvw:IEWinMain "" 1
fixme:ole:CoResumeClassObjects stub
Could not load Mozilla. HTML rendering will be disabled.
^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^^

J. Ernst [Jun 06]: I get the same thing even though I have mozilla installed. I'm using wine in 64-bit linux, though, so that probably has something to do with it. You don't need mozilla, but the Mozilla activex control : http://source.winehq.org/mozactivex I don't know why shdocvw doesn't prompt the user to install it in this case though (so I'm CCing wine-devel and Jacek to see if something has to be changed in nsembed.c). wine archive

Sound

Dlls

Graphics

A userposted: I want to run some program with Wine in a headless server. However, I want to access it via VNC, so I am using Xvnc (vncserver is a wrapper script) from tightvnc as a X server. But I have a problem: wine doesn't detect the display of the X server. This is what happens:

[redacted@private ~]$ DISPLAY=:1
[redacted@private ~]$ vncserver :1
New 'X' desktop is urano:1 (...)
[redacted@private ~]$ rm -rf .wine/ # just to be sure everything is clean
[redacted@private ~]$ winemine
wine: created the configuration directory '/home/redacted/.wine' ALSA lib [...]
CreateWindow failed with error -536870654 
err:wgl:process_attach X11DRV or GDI32 not loaded. Cannot create default context. 
wine: configuration in '/home/[redacted]/.wine' has been updated. 
Application tried to create a window, but no driver could be loaded.
Make sure that your X server is running and that $DISPLAY is set correctly. 

He then posted: It looks like I was setting incorrectly the environment variable, since this works: Code:

[redacted@private ~]$ DISPLAY=:1 winemine


fixme:d3d_draw:drawStridedFast >>>>>>>>>>>>>>>>> GL_OUT_OF_MEMORY (0x505) from glDrawArrays @ drawprim.c / 237

Vitamin [apr 09]: More invalid stuff - upgrade your nvidia drivers

X Error

X Error of failed request:  BadValue (integer parameter out of range for operation)
  Major opcode of failed request:  130 (XFree86-VidModeExtension)
  Minor opcode of failed request:  17 (XF86VidModeGetGammaRamp)

Nov 10 Vitamin: Either bad video drivers or you missing xmidmode extension (check /var/log/Xorg.*.log for details).

DIBSection

Winehq Bugzilla entry 20380 [looking in the traces a programmer noticed an] access violation when writing to read-only DIB image. (look for the accesses to address 0x1dd0000 in attachment)

in short, the we have: ---> create DIB image to render screen to 0009:trace:bitmap:CreateDIBSection format (800,-600), planes 1, bpp 16, size 960000, RGB ---> then render to our DIB image 0009:trace:bitblt:BitBlt hdcSrc=0x714 0,0 -> hdcDest=0x5cc 0,0 800x600 rop=cc0020 0009:trace:bitblt:X11DRV_StretchBlt vissrc=0,0-800,600 visdst=0,0-800,600

0009:trace:bitmap:X11DRV_DIB_Lock Locking 0x710 from thread 0009
0009:trace:bitmap:X11DRV_DIB_Coerce GdiMod requested in status AppMod
0009:trace:bitmap:X11DRV_DIB_DoProtectDIBSection Changed protection from 4 to 2
---> DIB image is read-only
X11DRV_DIB_DoUpdateDIBSection();
0009:trace:bitmap:X11DRV_DIB_DoCopyDIBSection Copying from DIB bits to Pixmap
0009:trace:bitmap:X11DRV_DIB_DoProtectDIBSection Changed protection from 2 to 1
---> and here we have not-accessible DIB image
0009:trace:bitmap:X11DRV_DIB_Unlock Unlocking in status GdiMod
0009:trace:bitmap:X11DRV_DIB_DoProtectDIBSection Changed protection from 1 to 2
---> but now DIB image only read-only!

---> and when we try to write 0009:trace:ddraw:IDirectDrawSurfaceImpl_Blt (0x1792d8)->(0x339ec4,0x1a71e8,0x339f98,1008000,(nil))

0009:trace:d3d_surface:IWineD3DBaseSurfaceImpl_LockRect (0x1793d8) : rect@0x339c24 flags(00000000), output lockedRect@0x339c0c, memory@0x1dd0000
---> we get SIGSEGV (address 01e54fe8 is within range
0x1dd0000-0x1ebb000) 0009:trace:seh:raise_exception code=c0000005 flags=0 addr=0x7ddacaf1 ip=7ddacaf1 tid=0009
0009:trace:seh:raise_exception info[0]=00000001
0009:trace:seh:raise_exception info[1]=01e54fe8
---> in exception handler we try to restore access flags for read/write
0009:trace:bitmap:X11DRV_DIB_Coerce AppMod requested in status InSync
0009:trace:bitmap:X11DRV_DIB_DoProtectDIBSection Changed protection from 2 to 4
---> ok, now DIB has r/w-access

This sequence (rw->r->no->r->seh->rw) is repeated again and again generating a log of exceptions and at some moment the program hangs. Disabling audio something helps, maybe because there is no additional threads created for audio processing, but access-violations don't disappear

This is the way the DIBSection code is supposed to work. The problem is that the content of a DIBSection needs to be around on the X11 side but programs also have to be able to access the data from a pointer. In order to synchronize both copies there is all this memory protection magic. In case of a Blt an exception is triggered when the memory copy isn't the latest revision of the image. This is not a problem.

Games which also give issues are ones which use Lock instead of Blt. In such cases we present the DIBSection memory directly to the app. Some programs (at least Populous) directly mess with the stack registers which prevents the memory protection code from recovering from the exception. This is very bad and we consider these apps broken (a DIB engine would fix this OR we shouldn't export the DIBSection memory directly to the app OR prevent the exception from occuring).

The code which I changed in Wine is related to the DIBSection code. Homm3 uses 16-bit and before we had to convert this 16-bit data to 24-bit on each upload (this would likely trigger the memory protection code as well). Due to my xrender work this conversion is not needed. Some code is different now (so perhaps somewhere I forgot to call some dib memory protection related code) or my code was fully correct but uncovered a new bug (I mean that when using the depth conversion, some code 'by accident' disarms the memory protections before they are presented to the app).


Based on what I described above, you might understand that the patch which you proposed is not a correct solution since this is how the DIBSection code should behave. The huge amount of exceptions which occurs is what makes the issue very hard to debug in combination with the fact that for some apps the stack gets corrupted which makes it very hard to find what code triggered the bug.

In case of Homm3 I would recommend to figure out first if the bug is not a result of Homm3 calling Lock/Unlock directly.

A. Julliard noted: the stack corruption is most likely because some apps use the %esp register while manipulating dibs. There's nothing we can do about that. Whoever came up with that hack should be shot.

Drivers

wine: Call from 0x7b8458b0 to unimplemented function ntoskrnl.exe.IoQueryDeviceDescription, aborting

Aug 08 wineuser vitamin: This is [a] driver. Make sure you removed your ~/.wine directory before installing this program. It could be a left-over from some other program. If this driver [is] part of your program, then you out of luck.

Usurp: you can try to change Windows version in winecfg to Windows ME/9x.

Copy Protection

Sometimes you wonder why a program is failing, and it can be due to the software having copy protection. Wine does not help reverse engineering of software protection but sometimes it can implement windows sufficiently for it to run. Unfortunately some which are apparently root kits will never see enough implemented on wine. However here are some snippets to help you recognize it is not wine's fault.


Winehq Bugzilla entry 10265 using wine 1.1.19 and get this output

fixme:reg:GetNativeSystemInfo (0x2deb855) using GetSystemInfo()
fixme:toolhelp:CreateToolhelp32Snapshot Unimplemented: heap list snapshot
fixme:thread:NtSetInformationThread info class 17 not supported yet ---

It will remain a problem until the publisher of the software repackages the app with a newer, more Wine compatible version of Themida software protection (>1.9.x). This is nothing Wine can fix

SEH

Time and or Date

A. Woods encountered a crash in the Gecko Runtime Environment (GRE) part of the installer when trying to install Mozilla 1.7.7. If he changed winver from winxp to win95, he didn't get this problem.

typing bt with Winver as XP gave:

 Backtrace:
=>1 0x557581df wine_cp_wcstombs(table=0x5584855c, flags=0x0, src=0x55c08a38, srclen=0x12, dst=0x99806858, dstlen=0x20, defchar=0x0, 
     used=0x0) [/var/tmp/portage/wine-cvs-1.1/work/wine/libs/unicode/wctomb.c:161] in libwine_unicode.so.1 (0x55c08934)
2 0x55a3a4f1 WideCharToMultiByte+0xe1(page=0x0, flags=0x0, src=0x55c08a38, srclen=0xffffffff, dst=0x99806858, dstlen=0x20, 
     defchar=0x0, used=0x0) [/var/tmp/portage/wine-cvs-1.1/work/wine/dlls/kernel/locale.c:1651] in kernel32 (0x55c08970)
3 0x60f61cfd PR_AttachThread+0x56a in nspr4 (0x55c08ae0)

He included a bit of the relay trace he and it includes the first occurance of that strange memory address (or anything near it for that matter). Since it's being passed into wine from Mozilla, I guess it is a problem within Mozilla.

WINEDEBUG +relay trace showed

0011:Call ntdll.RtlQueryTimeZoneInformation(55c08a34) ret=55a6fae5
0011:Ret  ntdll.RtlQueryTimeZoneInformation() retval=00000000 ret=55a6fae5
0011:Call ntdll.NtQuerySystemTime(55c08874) ret=55a6ebc5
0011:Ret  ntdll.NtQuerySystemTime() retval=00000000 ret=55a6ebc5
0011:Ret  kernel32.GetTimeZoneInformation() retval=00000000 ret=60f61cd6
0011:Call kernel32.WideCharToMultiByte(00000000,00000000,55c08a38 L"GMT Standard Time",ffffffff,99806858,00000020,00000000,00000000)
   ret=60f61cfd

J. Lang: Mozilla's passing an apparently invalid pointer to WideCharToMultiByte... Running with WINEDEBUG=nls may give a clue what string it's trying to convert, which may give some indication of the problem. Running with WINEDEBUG=relay will probably give a better clue, but be prepared for a huge log. But since the Mozilla source is available, you may be able to hunt it down more easily using that.

J. Hawkins pointed out that it installs in Windows XP but not in xp mode in wine: Just because Mozilla is passing a bad memory address doesn't mean it's a bug in Mozilla. For example Mozilla could have requested some information from wine and we gave them the bad memory address. Then they call WideCharToMultiByte with the bad memory address we gave them. Your best bet is to find the first place this bad memory address pops up. Having a copy of the Mozilla source would probably be a good thing for this exercise.

J. Lang: While that's certainly possible in general, [that this is a Wine only bug, it] doesn't appear to be the case here. The bad pointer is the destination address of WideCharToMultiByte, not the source. Typically this will some buffer or other internal to Mozilla. I'm not claiming there isn't a bug in Wine. But I think the immediate thing we're seeing is a bug in Mozilla (likely triggered by a bug in Wine.) The nls trace might be interesting, because the source pointer appears to be valid. So, what string are they trying to translate? An error message perhaps? That might point to the cause of the problem.

A. Woods supplied a WINEDEBUG +relay,+nls log of what's happening just before the invalid memory address gets passed back.

J. Lang: Sweet, this turns up what we're looking for. (That doesn't mean I have a patch though.) We're back to it being a Wine bug, though Moz is doing something moderately questionable.

 0011:Call kernel32.GetTimeZoneInformation(55c08a34) ret=60f61cd6
 0011:Call ntdll.RtlQueryTimeZoneInformation(55c08a34) ret=55a6fae5
 0011:Ret  ntdll.RtlQueryTimeZoneInformation() retval=00000000 ret=55a6fae5
 0011:Call ntdll.NtQuerySystemTime(55c08874) ret=55a6ebc5
 0011:Ret  ntdll.NtQuerySystemTime() retval=00000000 ret=55a6ebc5
 0011:Ret  kernel32.GetTimeZoneInformation() retval=00000000 ret=60f61cd6
 0011:Call kernel32.WideCharToMultiByte(00000000,00000000,55c08a38 L"GMT Standard time",ffffffff,99806858,00000020,00000000,00000000) 
    ret=60f61cfd

I went over to lxr.mozilla.org/seamonkey and searched for GetTimeZoneInformation. That produced the following file: http://lxr.mozilla.org/seamonkey/source/nsprpub/pr/src/md/windows/ntmisc.c They're doing a WideCharToMultiByte into the global variable _tzname. As the comment says, perhaps they shouldn't be.. Anyway, _tzname should live in msvcrt, but our include/msvcrt/time.h has:

/* FIXME: Must do something for _daylight, _dstbias, _timezone, _tzname */

Mozilla is almost certainly wrong, though: the maximum size for the TZ environment variable is 15 chars (16 with the NULL): http://msdn.microsoft.com/library/en-us/vclib/html/_crt__tzset.asp .The corresponding names in _tzname are probably only 3 chars in length, so 4 bytes long including the NULL terminator.

A. Julliard: Actually, judging from the pointer values I get on my XP box the buffers seem to be 64 chars long (though I agree they will probably always contain at most 3 chars). Still, I'm not sure why Mozilla feels the need to overwrite them, that doesn't seem right.


J. Lang summarised: The crash was due to Mozilla attempting to write to a value that's exported by msvcrt.dll. It was declared in msvcrt's spec file, but never defined. Thus Mozilla was writing to a garbage pointer. It's been fixed in Wine. There's a separate issue that Mozilla probably isn't doing the right thing. It's overwriting a buffer it doesn't own and whose size is not documented, and it should be writing only four characters but is writing more. Now that Wine is fixed this is unlikely to cause anyone any trouble, but it's still not right. [The discussion then turned to a patch for Mozilla] Wine Archive Link

Mouse

trace:dinput:SysMouseAImpl_SetCooperativeLevel (this=0x77c55f18,0x0008004c,0x00000006)
trace:dinput:SysMouseAImpl_SetCooperativeLevel  cooperative level : DISCL_FOREGROUND DISCL_NONEXCLUSIVE 
                                                                           -----------^

L. Ulmer: This means that the mouse cursor will NOT be hidden by DInput. So S3 really uses the standard GDI cursor at the same time than DInput. Dossinger: I just noticed that S3 has a registry setting called "GDIMouse". This setting is reflected by the "use colored mouse pointer(if possible)" / "use monochrome mouse pointer" settings. ("Benutze farbigen Mauszeiger(wennm=F6glich)" and "Benutze monochrimen Mauszeiger" in my German version). Changing this Setting has no effect on S3 in Wine. I suppose S3 fails to draw its own mouse pointer in Wine and falls back to the GDI one.

IRDA

Winehq Bugzilla entry 19397 has some examples of debugging this and comments on the traces [Jul 09]:<quote> From irdadump:

8:58:48.831478 i:cmd  > ca=2e pf=1 nr=0 ns=0 LM slsap=5b dlsap=00 CONN_CMD(6)
18:58:48.863541 i:rsp  < ca=2e pf=1 nr=1 ns=0 LM slsap=00 dlsap=5b CONN_RSP (5) 
18:58:48.863603 i:cmd  > ca=2e pf=1 nr=1 ns=1 LM slsap=5b dlsap=00 GET_VALUE_BY_CLASS: "HRM" "IrDA:TinyTP:LsapSel" (29)
18:58:48.907545 i:rsp  < ca=2e pf=1 nr=2 ns=1 LM slsap=00 dlsap=5b GET_VALUE_BY_CLASS: Success Integer: 43 (15)
18:58:48.907625 i:cmd  > ca=2e pf=1 nr=2 ns=2 LM slsap=5b dlsap=00 DISC (6)
18:58:48.938557 rr:rsp < ca=2e pf=1 nr=3 (2)
18:58:48.938606 i:cmd  > ca=2e pf=1 nr=2 ns=3 LM slsap=5c dlsap=43 CONN_CMD TTP credits=16 (7)
18:58:48.971811 i:rsp  < ca=2e pf=1 nr=4 ns=2 LM slsap=43 dlsap=5c CONN_RSP TTP credits=1 (7)

However the socket complains that it's not connected:

trace:winsock:WSASendTo socket 0088, wsabuf 0x1d9ea28, nbufs 1, flags 0, to (nil), tolen 0, ovl (nil), func (nil)
trace:winsock:WSASendTo fd=35, options=0 warn:winsock:wsaErrno errno 107, (Transport endpoint is not connected).

Looking at the log above, it appears as though there's a connection made (CONN_CMD), then it's disconnected (DISC), and the subsequent connect request (CONN_CMD) is the last thing done.

the Linux IrDA troubleshooting hints here: http://www.hpl.hp.com/personal/Jean_Tourrilhes/IrDA/#checking </end quote>

Raw Input

fixme:win:RegisterRawInputDevices (pRawInputDevices=0x229eb74, uiNumDevices=1, cbSize=12) stub!

V. Margolen [Oct-09]: This indicates it's trying to use rawinput which is 100% stubbed on Wine. Try setting win version to win2k.

CD or Hard drive

Winehq Bugzilla entry 21385 from a WINEDEBUG=+tid,+seh,+relay,+volume wine WSC2009.exe &> log.txt as well as checking info about iso mount point and block device permissions:

$ mount | grep iso
$ sudo losetup -a

and then for each listed block device from previous command: $ ls -l /dev/loopX (X=0,...)

fixme:ntdll:server_ioctl_file Unsupported ioctl 24000 (device=2 access=1 func=0 method=0)

Expected and harmless.

trace:volume:GetVolumeInformationW cannot open device L"\\\\.\\D:": err 5
trace:volume:GetDriveTypeW L"D:\\" -> 5

it looks like permission problem. Can you change to ownership of loop device node to your user ident? E.g. something like:

$ sudo chown <yourusername> /dev/loop0

MSVC

fixme:actctx:parse_assembly_elem wrong version for assemblymanifest: 8.0.50608.0 / 8.0.50727.4053
fixme:actctx:parse_manifest_buffer failed to parse manifest L"C:\\ProgramFiles\\VideoReDoTVSuite583\\Microsoft.VC80.MFCLOC.manifest"

V. Margolen[oct09]: Looks like you didn't install the correct version of msruntime.

Menu

Winehq Bugzilla entry 18175 Comment from Rein Klazes 2009-04-24 Well this is the interesting part:

0020:trace:menu:InsertMenuW hMenu 0x2e90, pos -1, flags 00000410, id 2f30,str L"Paragraph Alignment"
0020:trace:menu:MENU_InsertItem inserting at 4 by pos 1024
0020:trace:menu:do_debug_print_menuitem MENU_SetItemData from:  { ID=0x0 }
0020:trace:menu:MENU_SetItemData flags=410 str=0xb18f5c8
0020:trace:menu:do_debug_print_menuitem MENU_SetItemData to  :  {ID=0x2f30, Sub=0x2f30, fType=pop, Text=L"Paragraph Alignment" }
0020:trace:menu:InsertMenuW hMenu 0x2e90, pos -1, flags 00000400, id 000e,str L"Paragraph..."
0020:trace:menu:MENU_InsertItem inserting at 5 by pos 1024
0020:trace:menu:do_debug_print_menuitem MENU_SetItemData from:  { ID=0x0 }
0020:trace:menu:MENU_SetItemData flags=400 str=0xb18f5c8
0020:trace:menu:do_debug_print_menuitem MENU_SetItemData to  :  { ID=0xe,Text=L"Paragraph..." }
0020:trace:menu:InsertMenuW hMenu 0x2e90, pos -1, flags 00000410, id 2f80,str L"Bullets and Lists"
0020:trace:menu:MENU_InsertItem inserting at 6 by pos 1024
0020:trace:menu:do_debug_print_menuitem MENU_SetItemData from:  { ID=0x0 }
0020:trace:menu:MENU_SetItemData flags=410 str=0xb18f5c8
0020:trace:menu:do_debug_print_menuitem MENU_SetItemData to  :  {ID=0x2f80, Sub=0x2f80, fType=pop, Text=L"Bullets and Lists" }
0020:trace:menu:DestroyMenu (0x2f80)
0020:warn:menu:MENU_GetMenu invalid menu handle=0x2fd0, ptr=0xf13b48,magic=10 0020:trace:menu:DestroyMenu (0x2fd0)
0020:trace:menu:DestroyMenu (0x2f30)
0020:trace:menu:CreateMenu return 0x2f30 0020:trace:menu:CreateMenu return 0x2f80


You see that sub-popup menus are added ("Pargraph Alignment" and "Bulltest and Lists") BUT the handles of those popup menu's ( 2f30 and 2f80 ) are destroyed. A known issue for menu's is that Windows locks menu's as long as they are referenced by another menu but in Windows they will be destroyed making such menu's unworking. There is another bug report about this somewhere, but this is the better report. Fixing this is on my to do list somewhere, but there is some more urgent stuff as well. I will see what I can do.

If you can you can look in your 1.4GB file for the above lines and attach just that part.

Mdac

Winehq Bugzilla entry 15437

err:ole:CoGetClassObject class {00000507-0000-0010-8000-00aa006d2ea4} not registered
err:ole:create_server class {00000507-0000-0010-8000-00aa006d2ea4} not registered
err:ole:CoGetClassObject no class object {00000507-0000-0010-8000-00aa006d2ea4} could be created for context 0x5
wine: Unhandled exception 0x0eedfade at address 0x0000:0x7ee01eab (thread 002a), starting debugger...

L. Lenders: The game needs mdac to be installed. Likely invalid bug report.[..] do "winetricks mdac28" and the run tyhe installer again and report back please

Joystick

warn:dinput:find_joydevs Failed to open "/dev/input/event0": 13 Permesso negato

Vitamin [mar 09]This is your problem. Fix access to the event* device associated with your joystick.The user said: I've installed the system on this computer 15 days ago so these are the standard for my distro (kubuntu). Should I open a bug for my distro to change the owner of such files to root:plugdev? Vitamin: Yes it's a distro bug. Changing group or any other means of granting regular user access to their devices is fine.

M. Gregorie: If your distro uses udev (Unified device control), which it probably does, you can fix this yourself. The rules used by udev to set up devices are in /etc/udev/rules.d You shouldn't change the rules files because any kernel upgrade might overwrite them, but you can add a [file] with a custom file [to provide read-write access to your input device]. The rule that's affecting you is:

KERNEL=="mouse*|mice|event*", NAME="input/%k", MODE="0640" in '50-udev-default.rules'. These files are applied in lexical sort order at boot time, so you can add a file called, say, '55-my-custom.rules' to contain the following lines:

# Custom rules
#
# Give user,group and world read and write access to /dev/input/event*
#
KERNEL=="event*", MODE="0666"

This rule will override the access permissions set in '50-udev-default.rules'. You'll need to do this as root. Use any text editor (vi, emacs or gedit will all be fine) to create the file, which must be:

Check this once you've created it and use chown and/or chmod to fix ownership and access as necessary. If you try this be very careful not to change any of the existing files: you can upset the entire i/o system if you damage them. Make sure you keep a copy of your custom file somewhere safe. You may need it again. You'll almost certainly need to reinstall it if you do a clean install of a future Ubuntu release or change to a different distro.

Further Reading

USB

warn:file:wine_nt_to_unix_file_name L"serialui.dll" not found in /home/ben/.wine/dosdevices/c:/windows

A. English jan09: That's a false warning...it means it didn't see the fake dll we have for some dlls. Some apps check for the file name, rather than functionality. You can try overriding it with native, and see if that helps.


warn:file:CreateFileW Unable to create file L"\\\\.\\COM1" (status c0000034)

A. English: Does your program sees a serial port at all? If not, you might need to add some registry keys. A google search will show you few locations in registry where some programs might look for available serial ports.

The user wrote: Good question, thanks! I've run 'regedit' and searched the registry, and came up with HKEY_LOCAL_MACHINE\Software\Microsoft\Windows NT\CurrentVersion\Ports . Under it, there was a list containing LPT1:-3:, FILE:, and COM1:-5: . I added COM6:-9: just in case, exported the file, and copied the above section to HKEY_LOCAL_MACHINE\Software\Microsoft\Windows\CurrentVersion\Ports (the plain 'Windows' section didn't have a 'Ports' key.) After [the modification], the above are only reported for COM5 and up, which I suppose is a big improvement - presumably, it means that COM1-COM4 are operational. I'll check that out once I get back to my GPS.


err:winedevice:ServiceMain driver L"DK12DRV" failed to load
err:winedevice:ServiceMain driver L"hardlock" failed to load
err:winedevice:ServiceMain driver L"Haspnt" failed to load

Vitamin Apr 08: Those are "USB dongle" drivers - they won't work on Wine. I'm assuming that they came with your program. If that's the case - it will not work on Wine as-is.

Twain

Doing WINEDEBUG=+loaddll wine finereader.exe

...
trace:loaddll:load_dll Loaded module L"C:\\program files\\abbyy finereader 5.0 office\\scan\\scanman0.dll" : native
trace:loaddll:load_dll Loaded module L"c:\\windows\\system\\msvcrt.dll" : builtin
trace:loaddll:MODULE_FlushModrefs Unloaded module L"c:\\windows\\system\\msvcrt.dll" : builtin
err:module:load_builtin_dll loaded .so for L"Twain.dll" but got L"twain_32.dll" instead - probably 16-bit dll
trace:loaddll:MODULE_LoadModule16 Loaded module "c:\\windows\\Twain.dll" : builtin Scanning driver not ready.

S.Petreolle: "Builtin Scanning driver not ready" is suspicious. Has your linux scanner driver been loaded? Wine Archive Link

Memory

A programmer had been debugging why an n64 emulator ( Project64 ) gets "Failed to allocate memory" errors under wine 9.9.10 on linux kernel 2.6. [Mar 06] wine archive

The program allocates a large chunk of size 0x20100000, which succeeds, and then another large 0x10100000 chunk, which fails.

Wrote a test mmap binary to fill a process address space, it created a similar gap between the executable load address and the loaded shared libraries, eventually failing mmap calls when it hit the stack address space. When I updated the test app to explicitly mmap in the gap area via specifying the aligned start address, the mmap call succeeded. I can't be the first person to notice this. Are there any TODO solutions for this ?

One linux-centric solution would be to look for gaps like this in /proc/<pid>/maps in the libs/wine/mmap.c and take advantage of this. Or maybe another would be to keep a table of address spaces returned in wine_anon_mmap as a guide, then validate with try_mmap_fixed as to where a next-allocation should occur ( would this solution work outside linux )?

M McCormack: Wine's holey memory map has been discussed before:

The truely correct solution is probably to implement Windows compatible memory allocation in the Linux kernel, but there's other hacks that could be done in user space. Just a matter of finding something that Alexandre is willing to live with. A preload-ish type thing that overrode libc's mmap / munmap calls seems pausible to me.

[~/.wine/drive_c/Program Files/Warcraft III] wine war3.exe -opengl wine: Unhandled page fault on write
access to 0x00495000 at address 0x495000 (thread 0009), starting debugger...
=>1 0x00495000 EntryPoint in war3 (0x00495000) 2 0xf7f763ab wine_switch_to_stack+0x17 in libwine.so.1 (0xf7f763ab)
0x00495000 EntryPoint in war3: pushl    %eax

M. Meissner: Please run with:

And look for the virtual entries in the vicinity of 495000.

With the trace he added: Here is the culprit:

trace:virtual:VIRTUAL_SetProt 0x462000-0x4e7fff c-rW-
trace:virtual:VIRTUAL_DumpView View: 0x400000 - 0x57bfff (anonymous)
trace:virtual:VIRTUAL_DumpView       0x400000 - 0x400fff c-r--
trace:virtual:VIRTUAL_DumpView       0x401000 - 0x449fff c-r-x
trace:virtual:VIRTUAL_DumpView       0x44a000 - 0x57bfff c-rW-
This covers the 0x00495000 address. Note that the area lacks the x-bit.

A patch was offered. wine archive


fixme:virtual:NtAllocateVirtualMemory MEM_WRITE_WATCH type not supported

Vitamin: [mar09] This usually a sign of: 1. You using old Wine version (this is already implemented in the newer version) 2. This is .net app, which requires... dotnet installed.

Stack

err:syslevel:_EnterSysLevel (0x40797840, level 2): Holding 0x4083ccc0, 
level 3. Expect deadlock!
err:syslevel:_CheckNotSysLevel Holding lock 0x4083ccc0 level 3
err:seh:setup_exception stack overflow 176 bytes in thread 0009 eip 
004078d5 esp 405b0f50 stack 0x405b0000-0x406b0000

O.Stieber:The stack overflow looks like somethings got stuck in a loop, which is problably why there were pages and pages of messages.

M. Hern: I think this happens when you hit Ctrl-C and the thread the exception is delivered to is holding the GDI/USER syslevel. The Ctrl-C handler provided by the runtime attempts to open a message box and fails to re-enter the lower syslevel which in turn triggers the CheckNotLock assertion. That then throws another exception and we go into an infinite loop.

In other words I think we can ignore this as it only happens when you press Ctrl-C, something common on Linux but very rare on Windows.


A. Woods while debugging WoW: I'm attaching to the process with gdb, but it's not catching things at the point where they go wrong. Typically I am just seeing a stack like this though:

#0  0x56752a01 in ?? ()

T. Rollo If it's only giving one frame in the stack trace the cause is normally a corrupted stack, so you may need to examine the stack to try to figure out where the stack frame should be (starting with "x/256xw" may be helpful if the stack pointer is still valid).

Otherwise, when debugging with GDB without going through winedbg you may need to use the "pass" command to skip over first chance exceptions in some cases before you get to the real exception.



A programmer noted [Oct 05]: The stackspace usage in dlls/ntdll/directory.c is affecting programs. One installer crashes because of it I suspect.

A. Julliard pointed out a possibility: Is it by any chance because it does a recursive search of the disk and runs out of stack? If that's the case you'll most likely see the overflow happen in one of the directory.c functions, but they are not the real culprit since they are not themselves recursive. Wine Archive

Heap

Winehq Bugzilla entry 14867 Alexandre [has been] adding heap checks to Wine.

Winehq Bugzilla entry 21072 Dan Kegel 2009-12-19 21:02:22 noted: Your log has scary messages like

err:heap:HEAP_ValidateInUseArena Heap 0x110000: in-use arena 0x524c988 next block has PREV_FREE flag

which indicates a corrupt heap and means a crash is likely. How soon do the err:heap messages start showing up? [..] WINEDEBUG settings can accidentally make bugs go away (which qualifies them as Heisenbugs). If you see err:heap messages, it typically means you've hit either a wine bug or an app bug, and the next step may be to apply the heap checking patches, do winetricks heapcheck, and see if you get any interesting heap warnings. And the next step after that is to also run the app under valgrind... but that's hard, since it makes the app run Really Slow and take Lots Of Ram, and only pinpoints a bug occasionally. (But when it does, it's really the bomb.)


Winehq Bugzilla entry 1490

err:local:LOCAL_GetBlock not enough space in local heap

R. Klazes This actually has come up before in a thread "Upper Memory" not long ago in the newsgroup comp.emulators.ms-windows.wine. [..]

The problem is that the program reserves a fixed sized buffer to store the environment (the output what you see when you type "set" under DOS/Windows or "env" under Unix/Linux). What was more then enough for Windows 3.1, may not be enough under XP or Linux. If the supplier is unwilling to fix it, there are two ways to try to reduce the environment:

env -i PATH=$PATH DISPLAY=$DISPLAY wine yourprogram.exe

(the -i removes all variables, and I add the PATH and DISPLAY variables needed to find and run wine). There may be a few more other variables, TMP, TEMP, anything starting with LD_ needed or wine to run. If there are spaces in the paths involved it would be safer to use quotes:

env -i PATH="$PATH" DISPLAY=$DISPLAY XAUTHORITY="$XAUTHORITY" wine SMW.EXE


A programmer reported: The crash happens in the DDraw implementation. The return from Main_DirectDraw_Release(ddraw_main.c:154) leads to a random adress. The call which leads to this is "HeapFree(GetProcessHeap(), 0, This);" in Main_DirectDrawSurface_Destroy, surface_main.c:154. If I comment out this call, Empire Earth continues loading and crashes more or less randomly at some later points. I've edited the IDirectDrawSurfaceImpl structure and added a 2048 byte block at the beginning and the end. This makes the crashes reliable: With the HeapFree call, the ret jumps to NULL, and without the call Empire Earth crashes little later. BTW, Empire Earth crashes in exactly the same way in Cedega,

A second programmer replied: It probably has to do with some internal heap function, maybe some kind of buffer overrun somewhere. And since Cedega is basically a really old version of wine with a bunch of half-baked DX hacks in it, I would expect the crash to happen there as well.

The first programmer reported: This is interesting: Setting the +heap trace flag sets the bad address realiably to 0xaaaaaaaa(without my changes to DDraw). Does this say anything?

J. Ligget: Looks like an uninitialized value to me. I've seen similar cases like that, and that's what it was.

A. Mohr: dlls/ntdll/heap.c:#define ARENA_FREE_FILLER 0xaa

I'd guess this is an adress in an area that's actually gotten freed. Wine Archive


Winehq Bugzilla entry 21624 contains an example of debugging with heap

A. Focht: The problem is most likely buried within iphlpapi.GetNetworkParams() and use of dns resolver API.

Query the buffer size:

--- snip ---

002d:Call iphlpapi.GetNetworkParams(00000000,0457df5c) ret=03994f7e
002d:Ret  iphlpapi.GetNetworkParams() retval=0000006f ret=03994f7e ...
002d:trace:heap:RtlAllocateHeap (0x110000,70000062,00000270): returning 0x400a138

... --- snip ---

Fill the network/dns info into provided buffer:

--- snip ---

002d:Call iphlpapi.GetNetworkParams(0400a138,0457df5c) ret=03994f7e ...
002d:Call advapi32.RegQueryValueExA(000002e4,7e058bb9 "ScopeID",00000000,00000000,0400a270,0457dde4) ret=7e053c8b 
002d:Ret advapi32.RegQueryValueExA() retval=00000002 ret=7e053c8b ...
002d:Ret  iphlpapi.GetNetworkParams() retval=00000000 ret=03994f7e ---

snip ---

Relevant structures to calculate sizes (needed later):

--- snip include/iptypes.h ---

typedef struct {
char String[4 * 4];
} IP_ADDRESS_STRING, *PIP_ADDRESS_STRING, IP_MASK_STRING,*PIP_MASK_STRING;
typedef struct _IP_ADDR_STRING {
struct _IP_ADDR_STRING* Next;
IP_ADDRESS_STRING IpAddress;
IP_MASK_STRING IpMask;
DWORD Context;
} IP_ADDR_STRING, *PIP_ADDR_STRING;

...

typedef struct {
char HostName[MAX_HOSTNAME_LEN + 4] ;
charDomainName[MAX_DOMAIN_NAME_LEN + 4];
PIP_ADDR_STRING CurrentDnsServer;
IP_ADDR_STRING DnsServerList;
UINT NodeType;
char ScopeId[MAX_SCOPE_ID_LEN + 4];
UINT EnableRouting;
UINT EnableProxy;
UINT EnableDns;
} FIXED_INFO, *PFIXED_INFO;

--- snip include/iptypes.h ---

Sizes:

128+4 HostName
128+4 DomainName
4 CurrentDnsServer
40 DnsServerList
4 NodeType
256+4 ScopeId
4 EnableRouting
4 EnableProxy
4 EnableDns

Sum: 584 bytes -> 0x248 hex bytes

0x270 bytes from previous iphlpapi.GetNetworkParams() calls:

sizeof(FIXED_INFO) + sizeof(IP_ADDR_STRING) = two dns server entries. Additional dns server entries (_res.nscount > 1) are appended to struct FIXED_INFO.

Some time later (on different thread 0x3d):

--- snip ---

003d:Call iphlpapi.GetNetworkParams(00000000,0b7ddc50) ret=03994f7e
003d:Ret  iphlpapi.GetNetworkParams() retval=0000006f ret=03994f7e ...
003d:trace:heap:RtlAllocateHeap (0x110000,70000062,00000248): returning 0x4009aa0

...

003d:Call iphlpapi.GetNetworkParams(04009aa0,0b7ddc50) ret=03994f7e ...
003d:Call KERNEL32.GetComputerNameExA(00000001,04009aa0,0b7ddadc)ret=7e053b75 ...
003d:Ret  KERNEL32.GetComputerNameExA() retval=00000001 ret=7e053b75
003d:Call KERNEL32.GetComputerNameExA(00000002,04009b24,0b7ddadc)ret=7e053b9c ...
003d:Ret  KERNEL32.GetComputerNameExA() retval=00000001 ret=7e053b9c
003d:Call advapi32.RegOpenKeyExA(80000002,7e058870 "SYSTEM\\CurrentControlSet\\Services\\VxD\\MSTCP",00000000,00020019,0b7ddad8) ret=7e053c43
003d:Ret  advapi32.RegOpenKeyExA() retval=00000000 ret=7e053c43 003d:Call advapi32.RegQueryValueExA(000003b4,7e058bb9 
"ScopeID",00000000,00000000,04009bd8,0b7ddad4) ret=7e053c8b
0009:err:heap:HEAP_ValidateInUseArena Heap 0x110000: block 0x4009aa0 tail overwritten at 0x4009ce8 (byte 0/8 == 0x00)
003d:Ret advapi32.RegQueryValueExA() retval=00000002 ret=7e053c8b 

--- snip ---

This is where wine's heap detector raises its hand first time because the FIXED_INFO buffer was written past the end.

If you look closely you notice this time the GetNetworkParams() query for buffer size returned only 0x248 bytes - which is just sizeof(FIXED_INFO) = 1 dns server entry?!

Looking at the corresponding code: --- snip dlls/iphlpapi/ ---

DWORD WINAPI GetNetworkParams(PFIXED_INFO pFixedInfo, PULONG pOutBufLen) {
DWORD ret, size;
LONG regReturn;
HKEY hKey;
TRACE("pFixedInfo %p, pOutBufLen %p\n", pFixedInfo, pOutBufLen);
if (!pOutBufLen)
return ERROR_INVALID_PARAMETER;
initialise_resolver();
size = sizeof(FIXED_INFO) + (_res.nscount > 0 ? (_res.nscount - 1) * sizeof(IP_ADDR_STRING) : 0);
if (!pFixedInfo || *pOutBufLen < size) {
  • pOutBufLen = size;
return ERROR_BUFFER_OVERFLOW;
}
memset(pFixedInfo, 0, size);
size = sizeof(pFixedInfo->HostName);
GetComputerNameExA(ComputerNameDnsHostname, pFixedInfo->HostName, &size);
size = sizeof(pFixedInfo->DomainName);
GetComputerNameExA(ComputerNameDnsDomain, pFixedInfo->DomainName, &size);
if (_res.nscount > 0) {
PIP_ADDR_STRING ptr;
int i;
for (i = 0, ptr = &pFixedInfo->DnsServerList; i < _res.nscount && ptr; i++, ptr = ptr->Next) {
toIPAddressString(_res.nsaddr_list[i].sin_addr.s_addr, ptr->IpAddress.String);
if (i == _res.nscount - 1)
ptr->Next = NULL;
else if (i == 0)
ptr->Next = (PIP_ADDR_STRING)((LPBYTE)pFixedInfo + sizeof(FIXED_INFO));
else
ptr->Next = (PIP_ADDR_STRING)((PBYTE)ptr + sizeof(IP_ADDR_STRING));
}
}
pFixedInfo->NodeType = HYBRID_NODETYPE; regReturn = RegOpenKeyExA(HKEY_LOCAL_MACHINE, "SYSTEM\\CurrentControlSet\\Services\\VxD\\MSTCP", 0, KEY_READ, &hKey);
if (regReturn != ERROR_SUCCESS)
regReturn = RegOpenKeyExA(HKEY_LOCAL_MACHINE, "SYSTEM\\CurrentControlSet\\Services\\NetBT\\Parameters", 0,KEY_READ, &hKey);
if (regReturn == ERROR_SUCCESS) {
DWORD size = sizeof(pFixedInfo->ScopeId);
RegQueryValueExA(hKey, "ScopeID", NULL, NULL, (LPBYTE)pFixedInfo->ScopeId,&size);
RegCloseKey(hKey);
}

... --- snip dlls/iphlpapi/ ---

The only code that is able to write past the FIXED_INFO buffer is the dns server entries list population loop. If for some reason "_res.nscount" changes between overall buffer size calculation and dns server entries list population it could be possible to corrupt nearby block.

Now the question is: who can change "_res.nscount"? The API that might be the culprit is GetComputerNameExA( ComputerNameDnsHostname, ...) which is called in between "_res.nscount" queries.

dlls/kernel32/computername.c:

dns_hostname() -> dns_fqdn() -> gethostname() and
dns_gethostbyname()/gethostbyname_r()

So this code path seems potentially harmful to GetNetworkParams() as it might change "_res" dns resolver struct members implicitly.

Again this is just my theory how the memory corruption might be caused. I could be wrong as I can't reproduce the problem on my machine. For testing you could place a consistency check, comparing "_res.nscount" before and after GetComputerNameExA().

D. Kegel wrote: It turns out _res is thread-specific in glibc, so _res is uninitialized on all but the thread that called res_init(). [a patch was sent]

File Operations

 First, kernel/file.c's CreateFileW is called
> -------------
> trace:file:CreateFileW L"C:\\Program Files\\origin6.0\\UNTITLED.OPJ"
> GENERIC_READ GENERIC_WRITE FILE_SHARE_READ FILE_SHARE_WRITE  creation 5
> attributes 0x80
> -------------
> (creation 5 = TRUNCATE_EXISTING; attributes 0x80 = FILE_ATTRIBUTE_NORMAL)
> 
> which then calls NtCreateFile:
[...]
> Which fails then with:
> -------------
> warn:file:wine_nt_to_unix_file_name L"UNTITLED.OPJ" not found in /home/wine/.wine/dosdevices/c:/Program Files/origin6.0
> warn:ntdll:NtCreateFile L"\\??\\C:\\Program Files\\origin6.0\\UNTITLED.OPJ" not found (c0000034)
> warn:file:CreateFileW Unable to create file L"C:\\Program Files\\origin6.0\\UNTITLED.OPJ" (status c0000034)
> trace:file:CreateFileW returning 0xffffffff

A. Julliard: The problem is apparently that the app wants to create a new file using TRUNCATE_EXISTING, which fails if the file does not exist. So either the file should have been created earlier on, or the app is using the wrong creation argument for some reason.Wine Archive


warn:ntdll:NtCreateFile L"\\??\\C:" not found (c0000034)
warn:file:CreateFileW Unable to create file L"\\\\.\\C:" (status c0000034)

D. Riekenburg: [L"\\??\\" is the] internal shortcut for "\\DosDevices". c0000034 is STATUS_OBJECT_NAME_NOT_FOUND. Wine is unable to find the simulated "C:\" - Drive. Delete your config and create a new one. Wine Archive

Get File Attributes

trace:file:GetFileAttributesW L"c:\\Program Files\\THQ\\Gas Powered Games\\Supreme Commander\\sounds\\Voice\\fr\\Tutorials\\TUB500.xwb"
trace:file:RtlDosPathNameToNtPathName_U (L"c:\\Program Files\\THQ\\Gas Powered Games\\Supreme Commander\\sounds\\Voice\\fr\\Tutorials\\TUB500.xwb",0x334b84,(nil),(nil))
trace:file:RtlGetFullPathName_U (L"c:\\Program Files\\THQ\\Gas Powered Games\\Supreme Commander\\sounds\\Voice\\fr\\Tutorials\\TUB500.xwb" 520 0x3348f8 (nil))
warn:file:wine_nt_to_unix_file_name L"TUB500.xwb" not found in /home/stephan/.wine/dosdevices/c:/Program Files/THQ/Gas Powered Games/SupremeCommander/sounds/Voice/fr/Tutorials


R. Shearman [Jun 07 wine devel]: These messages are normal. GetFileAttributes is often used by programs to check for the existence of a file.

Move File

trace:file:MoveFileWithProgressW (L"",(null),(nil),(nil),0004)
trace:file:RtlDosPathNameToNtPathName_U (L"",0x3348b8,(nil),(nil))
  

R. Shearman [Jun 2007 wine devel]: This is not [normal]. Moving a file with a blank name isn't going to work properly. Probably a test case is needed to see what happens on Windows. However, my guess is that there is a bug elsewhere that causes the installer to not get the correct filename.

L"Territory",00000000,7c9bd738,7c9bd734,7c9bd730) ret=0081159d 000c:Call advapi32.RegQueryValueExW(00000138,008a440c
L"Territory",00000000,7c9bd270,7c9bd26c,7c9bd268) ret=0081159d

L Rayhen [nov 07] RegQueryValueExW retrieves the type and data for the specified value name associated with an open registry key. So it *may* be a problem only if called during unusually slow file operations hundreds times per second and not during typical (fast) file operations. To be sure it is better to use profiling tools (see below for more information).

[note: do not run wine as root,as was done in this example - root does not help, and causes more problems]

  warn:file:wine_nt_to_unix_file_name L"avicap32.dll" not found in /root/.wine/dosdevices/c:/windows/system32
  warn:file:wine_nt_to_unix_file_name L"avicap32.dll" not found in /root/.wine/dosdevices/c:/windows
  warn:file:wine_nt_to_unix_file_name L"winealsa.drv" not found in /root/.wine/dosdevices/c:/windows/system32/drivers
  warn:file:wine_nt_to_unix_file_name L"winealsa.drv" not found in /root/.wine/dosdevices/c:/windows/system32/drivers

L. Rayhen [nov 07] Often WINE searches multiples paths to find particular library but if at least one search succeeds there is no error and you can ignore these warnings (you can use "grep -v" to filter them out).

"/root/.wine/dosdevices/c:/windows/system32/wsock32.dll" required a case-insensitive search

L. Rayhen [nov 07] This just means that "windows/system32/WSOCK32.dll" doesn't exist but "windows/system32/wsock32.dll" does. In Windows file system there is no difference but most Linux file systems are case-sensitive. So in such situation case-insensitive search required (this might be slow but can be a problem only if you search for hundreds or thousands of files per seconds).

Slow File Operations

L. Rayhen [nov 07] Because you want to find out what functions in WINE are slow, it is bad idea to just use debugging channels and try to find them manually. Most likely you just waste a lot of time and find nothing. What you want to do is to profile WINE not to debug it (in fact there is no bugs to debug in this case but some inefficiencies in the code). Therefore proper approach is to use profiling tools to find out what functions are slow in WINE. Read [1] for a brief introduction. Read [2] to find out how to use callgrind tool for profiling (see page 39, "Callgrind: a call graph profiler"); there is some other useful information in this document. You may want to install kcachegrind and read its help files - this is useful visual tool, you can use it with callgrind and OProfile. I really recommend you to read its help - it's short but helpful. Use Google to find more information.


+ relay One dev wrote: does anyone notice a problem that the lines of the logging are written over each other as in the attached log?

My system has an AMD Phenom(tm) II X2 550 Processor on a NVIDIA GeForce 8300 Chipset running running Debian Lenny 32 bit Is this a know problem? Is a work around available?

--

003b:Call KERNEL32.lstrlenW(01812a90 L"C:\\windows\\temp\\PCULog0.0038:Call user32.Un003b:Ret KERNEL32.lstrlenW() retval=0000001b ret=01523b41 003b:Call KERNEL32.lstrcpynW(01813d98,01dbe708 L"C:\\windows\\temp\\P0038:Call user32.SetWindowsHookExW(003b:Ret KERNEL32.lstrcpynW() retval=01813d98 ret=0152397c 003b:Ret KERNEL32.GetVolumeInformationW() retval=00000001

H. Verbeet: that's a known problem. As a workaround you can use ">>" (append) instead of ">" to redirect to the file. You'll still need the "2>&1" to redirect stderr to stdout, of course. [..] The problem isn't the file being overwritten, it's multiple threads writing (mostly unsynchronized) to the same file.

M. Stefaniuc: The "overwrite" corruption is fixed by using ">>". So yes, when writting to a log file redirecting with ">>" is better. A. Julliard: Wine explicitly uses write(2) for debug output, and is careful about writing only complete lines precisely to avoid the interleaving issue. It does require O_APPEND to ensure that the writes don't step over each other, which is why you need ">>". It definitely makes a difference.

Managing traces and clearing clutter

If your log is too big, you have trouble making anything of it and just want to cry help...

wine ... 2>&1 | egr ep -v 'CriticalSec|SysLevel|Tls.etVal' >wine.log

M. Hearn in dealing with a difficult logWine Archive thread Link: I'm afraid this trace reveals little also (not your fault though!). Try doing it again with the following in RelayExclude: _EnterSysLevel;_LeaveSysLevel;RtlEnterCriticalSection;RtlLeaveCriticalSection;GDI_GetObjPtr;GDI_ReleaseObj

Further Reading

Personal tools
Namespaces
Variants
Actions
Navigation
Toolbox