Regression problems in app - help with debugging?

[Dr J A Gow]

Hello All,

I have some regression problems relating to Wine in a commercial ECAD 
app 'Easy-PC' version 9.0, available from http://www.numberone.com

The application was quite usable on Crossover Office 4.2, with just some 
minor dialog corruption. Alpha versions of Wine available at the same 
time (can not exactly remember which ones) could also run it 
successfully. However, under the latest Wine 0.9.6, Wine CVS and CXO 
5.0.1 it does not work. Note that it does not crash, it errors out 
cleanly with a dialog box message.

I have been debugging the problems in this app for some time now. It is 
a critical app for me as I use it in a production environment, but I do 
not want to pay Microsoft for the privilege of exposing my machine to 
malware. I am thus prepared to help debug Wine to get this application 
running. However, my Windows programming experience is limited to device 
drivers, not apps (although fluent C/C++ systems programming on other 
platforms), I have hit a brick wall, possibly due to my limited 
knowledge of how the Windows API works and I will need some help with this.

If anyone would like to help me debug this app (hope springs eternal!), 
a demo version of the app is available free of charge from the web site 
address above, and this version exhibits the same problems as the full 
version.

Background
-------------

The system: Dual physical processor (not dual core) Opteron running SuSE 
10.0 x86_64 SMP.
Wine: Latest 0.9.6 release, up to CVS grabbed a week or so ago.

The application installs OK and when run, puts up a GUI as expected. 
However, when you try to create a new PCB or schematic, an error dialog 
box is displayed indicating that the app can not read the technology 
file Default.stf (schematic) or Default.ptf (pcb). This is _not_ a 
permissions problem, all files are actually present and the same install 
will work under CXO 4.2.

I generated and analyzed several hundred MB of logfiles over many days, 
added extra debug statements to the Wine code and analyzed the 
application's operation. The problem actually appears to have two 
causes, and this is what I have come up with so far.

Problem 1
-----------

Application calls StgOpenStorage with a grfMode flag of 0x10020 
(STGM_TRANSACTED | STGM_SHARE_DENY_WRITE). Immediately afterwards it 
calls StorageBaseImpl_OpenStream with a grfMode of 0x12 
(STGM_SHARE_EXCLUSIVE | STGM_READWRITE). This second call fails with an 
access denied error code, after which the logs show an easily traced 
error handling sequence leading to display of the error dialog mentioned 
above:

0009:Call ole32.StgOpenStorage(59693db0 L"c:\\Program Files\\Number One Systems\\Easy-PC\\Technology\\Default.ptf",00000000,00010020,00000000,00000000,5821f850) ret=1022e7f0

...
...

trace:storage:StgOpenStorage <-- 00000000, IStorage 0x5b3465f8
0009:Ret  ole32.StgOpenStorage() retval=00000000 ret=1022e7f0

...
...

trace:storage:StorageBaseImpl_OpenStream (0x5b3465f8, L"\0005FileType", (nil), 12, 0, 0x5821f848)
fixme:storage:StorageBaseImpl_OpenStream STORAGE ACCESS DENIED - parent 0, this 2


Note that the last fixme is one I added to find out exactly what was 
going on here. Now, logic would dictate that the grfMode of the 
OpenStream method call is indeed incompatible with that of its parent 
storage object. However,  I would have thought that the application 
coders would most likely have hard-coded the grfMode flags in the 
application. If so, it would seem that the app is buggy, yet this 
application works on Windows! Either the app is buggy and the Win32 
OLE32 implementation behaves differently, or I am missing something here.

Ok, so with no obvious solution to this problem, I decided to bypass it. 
I modified the storage32.c implementation in the following way to bypass 
the grfMode check:

  parent_grfMode = STGM_ACCESS_MODE( This->ancestorStorage->base.openFlags );
  *if* ( STGM_ACCESS_MODE( grfMode ) > STGM_ACCESS_MODE( parent_grfMode ) )
  {

	FIXME("StorageBase_OpenStream called with grfMode mismatch - parent %d, this %d\n",
           parent_grfMode,STGM_ACCESS_MODE(grfMode));

    ///res = STG_E_ACCESSDENIED;/
    ///goto end;/
  }


Obviously not a viable fix, but a hack to get it working. After 
implementing this, the OpenStream call succeeded, as did subsequent 
stream access. However, the app _still_ errored out in exactly the same 
manner and at the same time. After more log searching, this led to the 
discovery of the second problem.

Problem 2
-----------

During its loading and setup, the application repeatedly calls 
StgOpenStorage on the .stf/.ptf files in question, calls OpenStream, 
reads from the stream, and then finally closes the storage. I placed 
tell-tales in useful locations in the file open/close handlers in the 
wineserver, and could clearly see the files being opened and 
subsequently closed. This open/read/close occurs correctly and in 
sequence up to a certain point. At this point in the execution, the app 
calls StgOpenStorage on the technology file, with the following call. It 
is opened correctly, with grfMode of STGM_TRANSACTED | 
STGM_SHARED_DENY_WRITE | STGM_READWRITE:

0009:Call ole32.StgOpenStorage(5821f754 L"c:\\Program Files\\Number One Systems\\Easy-PC\\Technology\\Default.ptf",00000000,00010022,00000000,00000000,5821f7f4) ret=7c17eabc
trace:storage:StgOpenStorage (L"c:\\Program Files\\Number One Systems\\Easy-PC\\Technology\\Default.ptf", (nil), 10022, (nil), 0, 0x5821f7f4)
...
...
...
trace:storage:StorageBaseImpl_AddRef (0x5b3465f8) AddRef to 1
trace:storage:StgOpenStorage <-- 00000000, IStorage 0x5b3465f8
0009:Ret  ole32.StgOpenStorage() retval=00000000 ret=7c17eabc

Almost immediately, the app opens three streams in this object and 
starts to access them, all successfully. There follows a whole slew of 
logging statements, all of which appear sensible However, what is 
strange about this access is that soon we seem to be frantically 
increasing the storage object's reference pointer. This sequence appears 
frequently in the code, closely spaced but interspersed with what seems 
quite logical and successful calls to seek functions and memory 
allocation functions:

0009:Call ntdll.RtlAllocateHeap(55890000,00000000,00000030) ret=584e498b
0009:Ret  ntdll.RtlAllocateHeap() retval=55926480 ret=584e498b
trace:storage:StorageBaseImpl_AddRef (0x5b3465f8) AddRef to 9
trace:storage:StorageImpl_ReadProperty storage name: L"\0005SummaryInformation"
0009:Call ntdll.RtlAllocateHeap(55890000,00000000,00000008) ret=584e7ab3
0009:Ret  ntdll.RtlAllocateHeap() retval=5594d108 ret=584e7ab3

The storage object's reference pointer is so incremented up to 19:

0009:Call ntdll.RtlAllocateHeap(55890000,00000000,00000030) ret=584e498b
0009:Ret  ntdll.RtlAllocateHeap() retval=559250f8 ret=584e498b
trace:storage:StorageBaseImpl_AddRef (0x5b3465f8) AddRef to 19
trace:storage:StorageImpl_ReadProperty storage name: L"\0005SummaryInformation"
0009:Call ntdll.RtlAllocateHeap(55890000,00000000,00000008) ret=584e7ab3
0009:Ret  ntdll.RtlAllocateHeap() retval=55925130 ret=584e7ab3

Finally, the code executes a

trace:storage:StgStreamImpl_Destroy (0x5b34b7e0)
trace:storage:StorageBaseImpl_Release (0x5b3465f8) ReleaseRef to 18


There follows a lot more log file, mostly concerned with set up and so 
on. What I am highligting here is that between this point, and the point 
of actual failure which I am going to describe shortly, there appears to 
be no attempt to close the Default.ptf file, unlike the attempts further 
up the logs closer to program start. I am wondering about this: is the 
reference counter being incorrectly incremented here, preventing the 
'Release' function from destroying the storage object and thus closing 
the file? I am not sufficiently familiar with the COM storage object 
stuff in Windows to know what _should_ happen here. Anyway. I will now 
describe the point of failure.

Further down the log, there are several more successful opens/closes of 
the technology file, with the correct mode flags. Then, finally, the app 
tries to re-open the technology file with a grfMode of STGM_TRANSACTED 
|  STGM_SHARE_DENY_WRITE. This call fails with a sharing violation 
(remember it had been left open from the previous call)

0009:Call ole32.StgOpenStorage(5971bec8 L"c:\\Program Files\\Number One Systems\\Easy-PC\\Technology\\Default.stf",00000000,00010020,00000000,00000000,5821e69c) ret=1022e7f0
....
.... 

0009:Ret  kernel32.CreateFileW() retval=ffffffff ret=584edc8b
trace:storage:StgOpenStorage <-- 80030020, IStorage (nil)


There then follows the same error handling sequence leading to display 
of the dialog.

I then thought about a simple test. I overrode the sharing mode 
detection in fd.c/check_sharing() in the wineserver (again, not a real 
solution). Note there are some minor differences in the code - I used a 
return code so I could easily check it:

///   if ((access & FILE_UNIX_READ_ACCESS) && !(existing_sharing & FILE_SHARE_READ))/
///		rc=0;/
///   if ((access & FILE_UNIX_WRITE_ACCESS) && !(existing_sharing & FILE_SHARE_WRITE))/
///		rc=0;/

///    if ((existing_access & FILE_UNIX_READ_ACCESS) && !(sharing & FILE_SHARE_READ)) rc=0;/
///    if ((existing_access & FILE_UNIX_WRITE_ACCESS) && !(sharing & FILE_SHARE_WRITE)) rc=0;/

    *if* (fd->closed->unlink[0] && !(existing_sharing & FILE_SHARE_DELETE)) rc=0;
    *if* (unlink && !(sharing & FILE_SHARE_DELETE)) rc=0;

	*if*(rc==0) {
		fprintf(stderr,"FILEDESC - sharing mode invalid\n");
		rc=1;
	}

    *return* rc;



and the application worked! Not only worked, but worked perfectly! The 
minor dialog corruption of previous versions had completely gone! I 
would like to thank the hard working people who have been working to 
correct problems in Wine, and in doing so had fixed this minor dialog 
problem. The only issue of note then is that the top-right hand buttons 
of a maximized MDI child window do not appear until you resize the 
frame. This is a minor issue though, and not of importance here.

However, what I did does not represent a real solution - I just hacked 
around the problem, which itself seems subtle in nature. I looked 
closely at the Microsoft documentation and the logic in check_sharing(), 
even writing a program in Windows to check that at the CreateFile level 
that the sharing logic in Wine is correct. It seems to be.

I am now stumped, I would really like to get this app working properly 
under Wine, without bad hacks. I would appreciate any guidance from 
those more experienced with the user-land Windows API. If you got this 
far, many thanks for taking the time to read this long message. I have 
provided only small excerpts from logs, but I can provide other parts of 
the files on request if necessary.

John.