Sweden-Number/documentation/winedev-otherdebug.sgml

  <chapter id="otherdebug">
    <title>Other debugging techniques</title>
    <sect1 id="hardware-trace">
      <title>Doing A Hardware Trace</title>

      <para>
        The primary reason to do this is to reverse engineer a
        hardware device for which you don't have documentation, but
        can get to work under Wine.
      </para>
      <para>
        This lot is aimed at parallel port devices, and in particular
        parallel port scanners which are now so cheap they are
        virtually being given away. The problem is that few
        manufactures will release any programming information which
        prevents drivers being written for Sane, and the traditional
        technique of using DOSemu to produce the traces does not work
        as the scanners invariably only have drivers for Windows.
      </para>
      <para>
        Presuming that you have compiled and installed wine the first
        thing to do is is to enable direct hardware access to your
        parallel port. To do this edit <filename>config</filename>
        (usually in <filename>~/.wine/</filename>) and in the
        ports section add the following two lines
      </para>
      <programlisting>
read=0x378,0x379,0x37a,0x37c,0x77a
write=0x378,x379,0x37a,0x37c,0x77a
      </programlisting>
      <para>
        This adds the necessary access required for SPP/PS2/EPP/ECP
        parallel port on LPT1. You will need to adjust these number
        accordingly if your parallel port is on LPT2 or LPT0.
      </para>
      <para>
        When starting wine use the following command line, where
        <literal>XXXX</literal> is the program you need to run in
        order to access your scanner, and <literal>YYYY</literal> is
        the file your trace will be stored in:
      </para>
      <programlisting>
WINEDEBUG=+io wine XXXX 2&gt; &gt;(sed 's/^[^:]*:io:[^ ]* //' &gt; YYYY)
      </programlisting>
      <para>
        You will need large amounts of hard disk space (read hundreds
        of megabytes if you do a full page scan), and for reasonable
        performance a really fast processor and lots of RAM.
      </para>
      <para>
	You will need to postprocess the output into a more manageable
	format, using the <command>shrink</command> program. First
        you need to compile the source (which is located at the end of
	this section):
      <programlisting>
cc shrink.c -o shrink
      </programlisting>
      </para>
      <para>
        Use the <command>shrink</command> program to reduce the
        physical size of the raw log as follows:
      </para>
      <programlisting>
cat log | shrink &gt; log2
      </programlisting>
      <para>
        The trace has the basic form of
      </para>
      <programlisting>
XXXX &gt; YY @ ZZZZ:ZZZZ
      </programlisting>
      <para>
        where <literal>XXXX</literal> is the port in hexadecimal being
        accessed, <literal>YY</literal> is the data written (or read)
        from the port, and <literal>ZZZZ:ZZZZ</literal> is the address
        in memory of the instruction that accessed the port. The
        direction of the arrow indicates whether the data was written
        or read from the port.
      </para>
      <programlisting>
&gt; data was written to the port
&lt; data was read from the port
      </programlisting>
      <para>
        My basic tip for interpreting these logs is to pay close
        attention to the addresses of the IO instructions. Their
        grouping and sometimes proximity should reveal the presence of
        subroutines in the driver. By studying the different versions
        you should be able to work them out. For example consider the
        following section of trace from my UMAX Astra 600P
      </para>
      <programlisting>
0x378 &gt; 55 @ 0297:01ec
0x37a &gt; 05 @ 0297:01f5
0x379 &lt; 8f @ 0297:01fa
0x37a &gt; 04 @ 0297:0211
0x378 &gt; aa @ 0297:01ec
0x37a &gt; 05 @ 0297:01f5
0x379 &lt; 8f @ 0297:01fa
0x37a &gt; 04 @ 0297:0211
0x378 &gt; 00 @ 0297:01ec
0x37a &gt; 05 @ 0297:01f5
0x379 &lt; 8f @ 0297:01fa
0x37a &gt; 04 @ 0297:0211
0x378 &gt; 00 @ 0297:01ec
0x37a &gt; 05 @ 0297:01f5
0x379 &lt; 8f @ 0297:01fa
0x37a &gt; 04 @ 0297:0211
0x378 &gt; 00 @ 0297:01ec
0x37a &gt; 05 @ 0297:01f5
0x379 &lt; 8f @ 0297:01fa
0x37a &gt; 04 @ 0297:0211
0x378 &gt; 00 @ 0297:01ec
0x37a &gt; 05 @ 0297:01f5
0x379 &lt; 8f @ 0297:01fa
0x37a &gt; 04 @ 0297:0211
      </programlisting>
      <para>
        As you can see there is a repeating structure starting at
        address <literal>0297:01ec</literal> that consists of four io
        accesses on the parallel port. Looking at it the first io
        access writes a changing byte to the data port the second
        always writes the byte <literal>0x05</literal> to the control
        port, then a value which always seems to
        <literal>0x8f</literal> is read from the status port at which
        point a byte <literal>0x04</literal> is written to the control
        port. By studying this and other sections of the trace we can
        write a C routine that emulates this, shown below with some
        macros to make reading/writing on the parallel port easier to
        read.
      </para>
      <programlisting>
#define r_dtr(x)        inb(x)
#define r_str(x)        inb(x+1)
#define r_ctr(x)        inb(x+2)
#define w_dtr(x,y)      outb(y, x)
#define w_str(x,y)      outb(y, x+1)
#define w_ctr(x,y)      outb(y, x+2)

/* Seems to be sending a command byte to the scanner */
int udpp_put(int udpp_base, unsigned char command)
{
    int loop, value;

    w_dtr(udpp_base, command);
    w_ctr(udpp_base, 0x05);

    for (loop=0; loop &lt; 10; loop++)
        if ((value = r_str(udpp_base)) & 0x80) 
	{
            w_ctr(udpp_base, 0x04);
            return value & 0xf8;
        }

    return (value & 0xf8) | 0x01;
}
      </programlisting>
      <para>
        For the UMAX Astra 600P only seven such routines exist (well
        14 really, seven for SPP and seven for EPP). Whether you
        choose to disassemble the driver at this point to verify the
        routines is your own choice. If you do, the address from the
        trace should help in locating them in the disassembly.
      </para>
      <para>
        You will probably then find it useful to write a script/perl/C
        program to analyse the logfile and decode them futher as this
        can reveal higher level grouping of the low level routines.
        For example from the logs from my UMAX Astra 600P when decoded
        further reveal (this is a small snippet)
      </para>
      <programlisting>
start:
put: 55 8f
put: aa 8f
put: 00 8f
put: 00 8f
put: 00 8f
put: c2 8f
wait: ff
get: af,87
wait: ff
get: af,87
end: cc
start:
put: 55 8f
put: aa 8f
put: 00 8f
put: 03 8f
put: 05 8f
put: 84 8f
wait: ff
      </programlisting>
      <para>
        From this it is easy to see that <varname>put</varname>
        routine is often grouped together in five successive calls
        sending information to the scanner. Once these are understood
        it should be possible to process the logs further to show the
        higher level routines in an easy to see format. Once the
        highest level format that you can derive from this process is
        understood, you then need to produce a series of scans varying
        only one parameter between them, so you can discover how to
        set the various parameters for the scanner.
      </para>

      <para>
        The following is the <filename>shrink.c</filename> program:
      <programlisting>
/* Copyright David Campbell &lt;campbell@torque.net&gt; */
#include &lt;stdio.h&gt;
#include &lt;string.h&gt;

int main (void)
{
    char buff[256], lastline[256] = "";
    int count = 0;

    while (!feof (stdin))
    {
        fgets (buff, sizeof (buff), stdin);
        if (strcmp (buff, lastline))
	{
	    if (count &gt; 1)
	        printf ("# Last line repeated %i times #\n", count);
	    printf ("%s", buff);
	    strcpy (lastline, buff);
	    count = 1;
	}
        else count++;
    }
    return 0;
}
      </programlisting>
      </para>
    </sect1>

    <sect1 id="undoc-func">
      <title>Understanding undocumented APIs</title>

      <para>
	Some background:  On the i386 class of machines, stack entries are
	usually dword (4 bytes) in size, little-endian. The stack grows
	downward in memory. The stack pointer, maintained in the 
	<literal>esp</literal> register, points to the last valid entry; 
	thus, the operation of pushing a value onto the stack involves 
	decrementing <literal>esp</literal> and then moving the value into 
	the memory pointed to by <literal>esp</literal>
	(i.e., <literal>push p</literal> in assembly resembles 
	<literal>*(--esp) = p;</literal> in C). Removing (popping)
	values off the stack is the reverse (i.e., <literal>pop p</literal> 
	corresponds to <literal>p = *(esp++);</literal> in C).
      </para>

      <para>
	In the <literal>stdcall</literal> calling convention, arguments are 
	pushed onto the stack right-to-left. For example, the C call
	<function>myfunction(40, 20, 70, 30);</function> is expressed in 
	Intel assembly as:
	<screen>
    push 30
    push 70
    push 20
    push 40
    call myfunction
	</screen>
	The called function is responsible for removing the arguments 
	off the stack. Thus, before the call to myfunction, the
	stack would look like:
	<screen>
             [local variable or temporary]
             [local variable or temporary]
              30
              70
              20
    esp ->    40
	</screen>
	After the call returns, it should look like:
	<screen>
             [local variable or temporary]
    esp ->   [local variable or temporary]
	</screen>
      </para>

      <para>
	To restore the stack to this state, the called function must know how
	many arguments to remove (which is the number of arguments it takes).
	This is a problem if the function is undocumented.
      </para>

      <para>
	One way to attempt to document the number of arguments each function
	takes is to create a wrapper around that function that detects the
	stack offset. Essentially, each wrapper assumes that the function will 
	take a large number of arguments. The wrapper copies each of these 
	arguments into its stack, calls the actual function, and then calculates 
	the number of arguments by checking esp before and after the call.
      </para>

      <para>
	The main problem with this scheme is that the function must actually
	be called from another program. Many of these functions are seldom
	used. An attempt was made to aggressively query each function in a
	given library (<filename>ntdll.dll</filename>) by passing 64 arguments, 
	all 0, to each function. Unfortunately, Windows NT quickly goes to a 
	blue screen of death, even if the program is run from a 
	non-administrator account.
      </para>

      <para>
	Another method that has been much more successful is to attempt to
	figure out how many arguments each function is removing from the
	stack. This instruction, <literal>ret hhll</literal> (where 
	<symbol>hhll</symbol> is the number of bytes to remove, i.e. the 
	number of arguments times 4), contains the bytes 
	<literal>0xc2 ll hh</literal> in memory. It is a reasonable
	assumption that few, if any, functions take more than 16 arguments; 
	therefore, simply searching for 
	<literal>hh == 0 && ll &lt; 0x40</literal>  starting from the 
	address of a function yields the correct number of arguments most 
	of the time.
      </para>

      <para>
	Of course, this is not without errors. <literal>ret 00ll</literal> 
	is not the only instruction that can have the byte sequence 
	<literal>0xc2 ll 0x0</literal>; for example, 
	<literal>push 0x000040c2</literal> has the byte sequence
	<literal>0x68 0xc2 0x40 0x0 0x0</literal>, which matches 
	the above. Properly, the utility should look for this sequence 
	only on an instruction boundary; unfortunately, finding 
	instruction boundaries on an i386 requires implementing a full 
	disassembler -- quite a daunting task. Besides, the probability 
	of having such a byte sequence that is not the actual return 
	instruction is fairly low.
      </para>

      <para>
	Much more troublesome is the non-linear flow of a function. For
	example, consider the following two functions:
	<screen>
    somefunction1:
        jmp  somefunction1_impl

    somefunction2:
        ret  0004

    somefunction1_impl:
        ret  0008
	</screen>
	In this case, we would incorrectly detect both 
	<function>somefunction1</function> and
	<function>somefunction2</function> as taking only a single 
	argument, whereas <function>somefunction1</function> really 
	takes two arguments.
      </para>

      <para>
	With these limitations in mind, it is possible to implement
	more stubs 
	in Wine and, eventually, the functions themselves.
      </para>
    </sect1>
    <sect1>
      <title>How to do regression testing using CVS</title>

      <para>
	A problem that can happen sometimes is 'it used to work
	before, now it doesn't anymore...'. Here is a step by step
	procedure to try to pinpoint when the problem occurred. This
	is <emphasis>NOT</emphasis> for casual users.
      </para>
      
      <orderedlist>
      <listitem>
	  <para>
	    Get the <quote>full CVS</quote> archive from winehq. This
	    archive is the CVS tree but with the tags controlling the
	    versioning system. It's a big file (> 40 meg) with a name
	    like full-cvs-&lt;last update date> (it's more than 100mb
	    when uncompressed, you can't very well do this with
	    small, old computers or slow Internet connections).
	  </para>
	</listitem>
	<listitem>
	  <para>
	    untar it into a repository directory:
	    <screen>
cd /home/gerard
tar -zxf full-cvs-2003-08-18.tar.gz
mv wine repository
	    </screen>
	  </para>
	</listitem>
	<listitem>
	  <para>
	    extract a new destination directory. This directory must
	    not be in a subdirectory of the repository else
	    <command>cvs</command> will think it's part of the
	    repository and deny you an extraction in the repository:
	    <screen>
cd /home/gerard
mv wine wine_current (-> this protects your current wine sandbox, if any)
export CVSROOT=/home/gerard/repository
cvs -d $CVSROOT checkout wine
	    </screen>
	  </para>
	  <para>
	    Note that it's not possible to do a checkout at a given
	    date; you always do the checkout for the last date where
	    the full-cvs-xxx snapshot was generated.
	  </para>
	  <para>
	    Note also that it is possible to do all this with a direct
	    CVS connection, of course. The full CVS file method is less
	    painful for the WineHQ CVS server and probably a bit faster
	    if you don't have a very good net connection.
	  </para>
	</listitem>
	<listitem>
	  <para>
	    you will have now in the <filename>~/wine</filename>
	    directory an image of the CVS tree, on the client side.
	    Now update this image to the date you want:
	    <screen>
cd /home/gerard/wine
cvs update -PAd -D "2004-08-23 CDT"   
	    </screen>
	  </para>
	  <para>
	    The date format is <literal>YYYY-MM-DD HH:MM:SS</literal>.
	    Using the CST date format ensure that you will be able to
	    extract patches in a way that will be compatible with the
	    wine-cvs archive
	    <ulink url="http://www.winehq.org/hypermail/wine-cvs">
	      http://www.winehq.org/hypermail/wine-cvs</ulink>
	  </para>
	  <para>
	    Many messages will inform you that more recent files have
	    been deleted to set back the client cvs tree to the date
	    you asked, for example:
	    <screen>
cvs update: tsx11/ts_xf86dga2.c is no longer in the repository
	    </screen>
	  </para>
	  <para>
	    <command>cvs update</command> is not limited to upgrade to
	    a <emphasis>newer</emphasis> version as I have believed for
	    far too long :-(
	  </para>
	</listitem>
	<listitem>
	  <para>
	    Now proceed as for a normal update:
	  </para>
	  <screen>
./configure
make depend && make
	  </screen>
	  <para>
	    If any non-programmer reads this, the fastest method to
	    get at the point where the problem occurred is to use a
	    binary search, that is, if the problem occurred in 1999,
	    start at mid-year, then is the problem is already here,
	    back to 1st April, if not, to 1st October, and so on.
	  </para>
	  <para>
	    If you have lot of hard disk free space (a full compile
	    currently takes 400 Mb), copy the oldest known working
	    version before updating it, it will save time if you need
	    to go back. (it's better to <command>make
	      distclean</command> before going back in time, so you
	    have to make everything if you don't backup the older
	    version)
	  </para>
	  <para>
	    When you have found the day where the problem happened,
	    continue the search using the wine-cvs archive (sorted by
	    date) and a more precise cvs update including hour,
	    minute, second: 
	    <screen>
cvs update -PAd -D "2004-08-23 15:17:25 CDT"
	    </screen>
	    This will allow you to find easily the exact patch that
	    did it.
	  </para>
	</listitem>
	<listitem>
	  <para>
	    If you find the patch that is the cause of the problem,
	    you have almost won; report about it to
	    <ulink url="http://bugs.winehq.org/">Wine Bugzilla</ulink>
	    or subscribe to wine-devel and post it there. There is a
	    chance that the author will jump in to suggest a fix; or
	    there is always the possibility to look hard at the patch
	    until it is coerced to reveal where is the bug :-) 
	  </para>
	</listitem>
      </orderedlist>
    </sect1>
    <sect1>
      <title>Which code has been tested?</title>
      <para>
        Deciding what code should be tested next can be a difficult
        decision.  And in any given project, there is always code that
        isn't tested where bugs could be lurking.  This section goes
        over how to identify these sections using a tool called gcov.
      </para>
      <para>
        To use gcov on wine, do the following:
      </para>
      <orderedlist>
        <listitem>
         <para>
           In order to activate code coverage in the wine source code,
           when running <command>make</command> set
           <literal>CFLAGS</literal> like so <command>make
           CFLAGS="-fprofile-arcs -ftest-coverage"</command>.  Note that
           this can be done at any directory level.  Since compile 
           and run time are significantly  increased by these flags, you
           may want to only use these flags inside a given dll directory.
         </para>
       </listitem>
        <listitem>
         <para>
           Run any application or test suite.
         </para>
       </listitem>
        <listitem>
         <para>
           Run gcov on the file which you would like to know more
           about code coverage.
         </para>
       </listitem>
      </orderedlist>
      <para>
        The following is an example situation when using gcov to
        determine the coverage of a file could be helpful.  We'll use
        the <filename>dlls/lzexpand/lzexpand_main.c.</filename> file.
        At one time the code in this file was not fully tested (as it
        may still be).  For example at the time of this writing, the
        function <function>LZOpenFileA</function> had the following
        lines in it:
        <screen>
if ((mode&~0x70)!=OF_READ)
        return fd;
if (fd==HFILE_ERROR)
        return HFILE_ERROR;
cfd=LZInit(fd);
if ((INT)cfd <= 0) return fd;
return cfd;
        </screen>
        Currently there are a few tests written to test this function;
        however, these tests don't check that everything is correct.
        For instance, <constant>HFILE_ERROR</constant> may be the wrong
        error code to return.  Using gcov and directed tests, we can
        validate the correctness of this line of code.  First, we see
        what has been tested already by running gcov on the file. 
        To do this, do the following:
        <screen>
cvs checkout wine
mkdir build
cd build
../wine/configure
make depend && make CFLAGS="-fprofile-arcs -ftest-coverage"
cd dlls/lxexpand/tests
make test
cd ..
gcov ../../../wine/dlls/lzexpand/lzexpand_main.c
  0.00% of 3 lines executed in file ../../../wine/include/wine/unicode.h
  Creating unicode.h.gcov.
  0.00% of 4 lines executed in file /usr/include/ctype.h
  Creating ctype.h.gcov.
  0.00% of 6 lines executed in file /usr/include/bits/string2.h
  Creating string2.h.gcov.
  100.00% of 3 lines executed in file ../../../wine/include/winbase.h
  Creating winbase.h.gcov.
  50.83% of 240 lines executed in file ../../../wine/dlls/lzexpand/lzexpand_main.c
  Creating lzexpand_main.c.gcov.
less lzexpand_main.c.gcov
        </screen>
        Note that there is more output, but only output of gcov is
        shown.  The output file
        <filename>lzexpand_main.c.gcov</filename> looks like this.
        <screen>
        9:  545:        if ((mode&~0x70)!=OF_READ)
        6:  546:                return fd;
        3:  547:        if (fd==HFILE_ERROR)
    #####:  548:                return HFILE_ERROR;
        3:  549:        cfd=LZInit(fd);
        3:  550:        if ((INT)cfd <= 0) return fd;
        3:  551:        return cfd;
        </screen>
        <command>gcov</command> output consists of three components:
        the number of times a line was run, the line number, and the
        actual text of the line.  Note: If a line is optimized out by
        the compiler, it will appear as if it was never run.  The line
        of code which returns <constant>HFILE_ERROR</constant> is
        never executed (and it is highly unlikely that it is optimized
        out), so we don't know if it is correct.  In order to validate
        this line, there are two parts of this process.  First we must
        write the test.  Please see <xref linkend="testing"> to
        learn more about writing tests.  We insert the following lines
        into a test case:
        <screen>
INT file;

/* Check for nonexistent file */
file = LZOpenFile("badfilename_", &amp;test, OF_READ);
ok(file == LZERROR_BADINHANDLE, 
   "LZOpenFile succeeded on nonexistent file\n");
LZClose(file);
       </screen>
       Once we add in this test case, we now want to know if the line
       in question is run by this test and works as expected.  You
       should be in the same directory as you left off in the previous
       command example.  The only difference is that we have to remove
       the <filename>*.da</filename> files in order to start the
       count over (if we leave the files than the number of times the
       line is run is just added, e.g. line 545 below would be run 19 times)
       and we remove the <filename>*.gcov</filename> files because
       they are out of date and need to be recreated.
      </para>
      <screen>
rm *.da *.gcov
cd tests
make
make test
cd ..
gcov ../../../wine/dlls/lzexpand/lzexpand_main.c
  0.00% of 3 lines executed in file ../../../wine/include/wine/unicode.h
  Creating unicode.h.gcov.
  0.00% of 4 lines executed in file /usr/include/ctype.h
  Creating ctype.h.gcov.
  0.00% of 6 lines executed in file /usr/include/bits/string2.h
  Creating string2.h.gcov.
  100.00% of 3 lines executed in file ../../../wine/include/winbase.h
  Creating winbase.h.gcov.
  51.67% of 240 lines executed in file ../../../wine/dlls/lzexpand/lzexpand_main.c
  Creating lzexpand_main.c.gcov.
less lzexpand_main.c.gcov
      </screen>
      <para>
        Note that there is more output, but only output of gcov is
        shown.  The output file
        <filename>lzexpand_main.c.gcov</filename> looks like this.
      </para>
      <screen>
       10:  545:        if ((mode&~0x70)!=OF_READ)
        6:  546:                return fd;
        4:  547:        if (fd==HFILE_ERROR)
        1:  548:                return HFILE_ERROR;
        3:  549:        cfd=LZInit(fd);
        3:  550:        if ((INT)cfd <= 0) return fd;
        3:  551:        return cfd;
      </screen>
      <para>
        Based on gcov, we now know that
        <constant>HFILE_ERROR</constant> is returned once.  And since
        all of our other tests have remain unchanged, we can assume
        that the one time it is returned is to satisfy the one case we
        added where we check for it.  Thus we have validated a line of
        code.  While this is a cursory example, it demostrates the
        potential usefulness of this tool.  
      </para>
      <para>
        For a further in depth description of gcov, the official gcc
        compiler suite page for gcov is <ulink
        url="http://gcc.gnu.org/onlinedocs/gcc-3.2.3/gcc/Gcov.html">
        http://gcc.gnu.org/onlinedocs/gcc-3.2.3/gcc/Gcov.html</ulink>.
        There is also an excellent article written by Steve Best for
        Linux Magazine which describes and illustrates this process
        very well at
        <ulink url="http://www.linux-mag.com/2003-07/compile_01.html">
        http://www.linux-mag.com/2003-07/compile_01.html</ulink>. 
      </para>
    </sect1>

  </chapter>

<!-- Keep this comment at the end of the file
Local variables:
mode: sgml
sgml-parent-document:("wine-devel.sgml" "set" "book" "part" "chapter" "")
End:
-->