documentation/winedev-otherdebug.sgml

   1   <chapter id="otherdebug">
   2     <title>Other debugging techniques</title>
   3     <sect1 id="hardware-trace">
   4       <title>Doing A Hardware Trace</title>
   5
   6       <para>
   7         The primary reason to do this is to reverse engineer a
   8         hardware device for which you don't have documentation, but
   9         can get to work under Wine.
  10       </para>
  11       <para>
  12         This lot is aimed at parallel port devices, and in particular
  13         parallel port scanners which are now so cheap they are
  14         virtually being given away. The problem is that few
  15         manufactures will release any programming information which
  16         prevents drivers being written for Sane, and the traditional
  17         technique of using DOSemu to produce the traces does not work
  18         as the scanners invariably only have drivers for Windows.
  19       </para>
  20       <para>
  21         Presuming that you have compiled and installed wine the first
  22         thing to do is is to enable direct hardware access to your
  23         parallel port. To do this edit <filename>config</filename>
  24         (usually in <filename>~/.wine/</filename>) and in the
  25         ports section add the following two lines
  26       </para>
  27       <programlisting>
  28 read=0x378,0x379,0x37a,0x37c,0x77a
  29 write=0x378,x379,0x37a,0x37c,0x77a
  30       </programlisting>
  31       <para>
  32         This adds the necessary access required for SPP/PS2/EPP/ECP
  33         parallel port on LPT1. You will need to adjust these number
  34         accordingly if your parallel port is on LPT2 or LPT0.
  35       </para>
  36       <para>
  37         When starting wine use the following command line, where
  38         <literal>XXXX</literal> is the program you need to run in
  39         order to access your scanner, and <literal>YYYY</literal> is
  40         the file your trace will be stored in:
  41       </para>
  42       <programlisting>
  43 WINEDEBUG=+io wine XXXX 2&gt; &gt;(sed 's/^[^:]*:io:[^ ]* //' &gt; YYYY)
  44       </programlisting>
  45       <para>
  46         You will need large amounts of hard disk space (read hundreds
  47         of megabytes if you do a full page scan), and for reasonable
  48         performance a really fast processor and lots of RAM.
  49       </para>
  50       <para>
  51         You will need to postprocess the output into a more manageable
  52         format, using the <command>shrink</command> program. First
  53         you need to compile the source (which is located at the end of
  54         this section):
  55       <programlisting>
  56 cc shrink.c -o shrink
  57       </programlisting>
  58       </para>
  59       <para>
  60         Use the <command>shrink</command> program to reduce the
  61         physical size of the raw log as follows:
  62       </para>
  63       <programlisting>
  64 cat log | shrink &gt; log2
  65       </programlisting>
  66       <para>
  67         The trace has the basic form of
  68       </para>
  69       <programlisting>
  70 XXXX &gt; YY @ ZZZZ:ZZZZ
  71       </programlisting>
  72       <para>
  73         where <literal>XXXX</literal> is the port in hexadecimal being
  74         accessed, <literal>YY</literal> is the data written (or read)
  75         from the port, and <literal>ZZZZ:ZZZZ</literal> is the address
  76         in memory of the instruction that accessed the port. The
  77         direction of the arrow indicates whether the data was written
  78         or read from the port.
  79       </para>
  80       <programlisting>
  81 &gt; data was written to the port
  82 &lt; data was read from the port
  83       </programlisting>
  84       <para>
  85         My basic tip for interpreting these logs is to pay close
  86         attention to the addresses of the IO instructions. Their
  87         grouping and sometimes proximity should reveal the presence of
  88         subroutines in the driver. By studying the different versions
  89         you should be able to work them out. For example consider the
  90         following section of trace from my UMAX Astra 600P
  91       </para>
  92       <programlisting>
  93 0x378 &gt; 55 @ 0297:01ec
  94 0x37a &gt; 05 @ 0297:01f5
  95 0x379 &lt; 8f @ 0297:01fa
  96 0x37a &gt; 04 @ 0297:0211
  97 0x378 &gt; aa @ 0297:01ec
  98 0x37a &gt; 05 @ 0297:01f5
  99 0x379 &lt; 8f @ 0297:01fa
 100 0x37a &gt; 04 @ 0297:0211
 101 0x378 &gt; 00 @ 0297:01ec
 102 0x37a &gt; 05 @ 0297:01f5
 103 0x379 &lt; 8f @ 0297:01fa
 104 0x37a &gt; 04 @ 0297:0211
 105 0x378 &gt; 00 @ 0297:01ec
 106 0x37a &gt; 05 @ 0297:01f5
 107 0x379 &lt; 8f @ 0297:01fa
 108 0x37a &gt; 04 @ 0297:0211
 109 0x378 &gt; 00 @ 0297:01ec
 110 0x37a &gt; 05 @ 0297:01f5
 111 0x379 &lt; 8f @ 0297:01fa
 112 0x37a &gt; 04 @ 0297:0211
 113 0x378 &gt; 00 @ 0297:01ec
 114 0x37a &gt; 05 @ 0297:01f5
 115 0x379 &lt; 8f @ 0297:01fa
 116 0x37a &gt; 04 @ 0297:0211
 117       </programlisting>
 118       <para>
 119         As you can see there is a repeating structure starting at
 120         address <literal>0297:01ec</literal> that consists of four io
 121         accesses on the parallel port. Looking at it the first io
 122         access writes a changing byte to the data port the second
 123         always writes the byte <literal>0x05</literal> to the control
 124         port, then a value which always seems to
 125         <literal>0x8f</literal> is read from the status port at which
 126         point a byte <literal>0x04</literal> is written to the control
 127         port. By studying this and other sections of the trace we can
 128         write a C routine that emulates this, shown below with some
 129         macros to make reading/writing on the parallel port easier to
 130         read.
 131       </para>
 132       <programlisting>
 133 #define r_dtr(x)        inb(x)
 134 #define r_str(x)        inb(x+1)
 135 #define r_ctr(x)        inb(x+2)
 136 #define w_dtr(x,y)      outb(y, x)
 137 #define w_str(x,y)      outb(y, x+1)
 138 #define w_ctr(x,y)      outb(y, x+2)
 139
 140 /* Seems to be sending a command byte to the scanner */
 141 int udpp_put(int udpp_base, unsigned char command)
 142 {
 143     int loop, value;
 144
 145     w_dtr(udpp_base, command);
 146     w_ctr(udpp_base, 0x05);
 147
 148     for (loop=0; loop &lt; 10; loop++)
 149         if ((value = r_str(udpp_base)) & 0x80)
 150         {
 151             w_ctr(udpp_base, 0x04);
 152             return value & 0xf8;
 153         }
 154
 155     return (value & 0xf8) | 0x01;
 156 }
 157       </programlisting>
 158       <para>
 159         For the UMAX Astra 600P only seven such routines exist (well
 160         14 really, seven for SPP and seven for EPP). Whether you
 161         choose to disassemble the driver at this point to verify the
 162         routines is your own choice. If you do, the address from the
 163         trace should help in locating them in the disassembly.
 164       </para>
 165       <para>
 166         You will probably then find it useful to write a script/perl/C
 167         program to analyse the logfile and decode them futher as this
 168         can reveal higher level grouping of the low level routines.
 169         For example from the logs from my UMAX Astra 600P when decoded
 170         further reveal (this is a small snippet)
 171       </para>
 172       <programlisting>
 173 start:
 174 put: 55 8f
 175 put: aa 8f
 176 put: 00 8f
 177 put: 00 8f
 178 put: 00 8f
 179 put: c2 8f
 180 wait: ff
 181 get: af,87
 182 wait: ff
 183 get: af,87
 184 end: cc
 185 start:
 186 put: 55 8f
 187 put: aa 8f
 188 put: 00 8f
 189 put: 03 8f
 190 put: 05 8f
 191 put: 84 8f
 192 wait: ff
 193       </programlisting>
 194       <para>
 195         From this it is easy to see that <varname>put</varname>
 196         routine is often grouped together in five successive calls
 197         sending information to the scanner. Once these are understood
 198         it should be possible to process the logs further to show the
 199         higher level routines in an easy to see format. Once the
 200         highest level format that you can derive from this process is
 201         understood, you then need to produce a series of scans varying
 202         only one parameter between them, so you can discover how to
 203         set the various parameters for the scanner.
 204       </para>
 205
 206       <para>
 207         The following is the <filename>shrink.c</filename> program:
 208       <programlisting>
 209 /* Copyright David Campbell &lt;campbell@torque.net&gt; */
 210 #include &lt;stdio.h&gt;
 211 #include &lt;string.h&gt;
 212
 213 int main (void)
 214 {
 215     char buff[256], lastline[256] = "";
 216     int count = 0;
 217
 218     while (!feof (stdin))
 219     {
 220         fgets (buff, sizeof (buff), stdin);
 221         if (strcmp (buff, lastline))
 222         {
 223             if (count &gt; 1)
 224                 printf ("# Last line repeated %i times #\n", count);
 225             printf ("%s", buff);
 226             strcpy (lastline, buff);
 227             count = 1;
 228         }
 229         else count++;
 230     }
 231     return 0;
 232 }
 233       </programlisting>
 234       </para>
 235     </sect1>
 236
 237     <sect1 id="undoc-func">
 238       <title>Understanding undocumented APIs</title>
 239
 240       <para>
 241         Some background:  On the i386 class of machines, stack entries are
 242         usually dword (4 bytes) in size, little-endian. The stack grows
 243         downward in memory. The stack pointer, maintained in the
 244         <literal>esp</literal> register, points to the last valid entry;
 245         thus, the operation of pushing a value onto the stack involves
 246         decrementing <literal>esp</literal> and then moving the value into
 247         the memory pointed to by <literal>esp</literal>
 248         (i.e., <literal>push p</literal> in assembly resembles
 249         <literal>*(--esp) = p;</literal> in C). Removing (popping)
 250         values off the stack is the reverse (i.e., <literal>pop p</literal>
 251         corresponds to <literal>p = *(esp++);</literal> in C).
 252       </para>
 253
 254       <para>
 255         In the <literal>stdcall</literal> calling convention, arguments are
 256         pushed onto the stack right-to-left. For example, the C call
 257         <function>myfunction(40, 20, 70, 30);</function> is expressed in
 258         Intel assembly as:
 259         <screen>
 260     push 30
 261     push 70
 262     push 20
 263     push 40
 264     call myfunction
 265         </screen>
 266         The called function is responsible for removing the arguments
 267         off the stack. Thus, before the call to myfunction, the
 268         stack would look like:
 269         <screen>
 270              [local variable or temporary]
 271              [local variable or temporary]
 272               30
 273               70
 274               20
 275     esp ->    40
 276         </screen>
 277         After the call returns, it should look like:
 278         <screen>
 279              [local variable or temporary]
 280     esp ->   [local variable or temporary]
 281         </screen>
 282       </para>
 283
 284       <para>
 285         To restore the stack to this state, the called function must know how
 286         many arguments to remove (which is the number of arguments it takes).
 287         This is a problem if the function is undocumented.
 288       </para>
 289
 290       <para>
 291         One way to attempt to document the number of arguments each function
 292         takes is to create a wrapper around that function that detects the
 293         stack offset. Essentially, each wrapper assumes that the function will
 294         take a large number of arguments. The wrapper copies each of these
 295         arguments into its stack, calls the actual function, and then calculates
 296         the number of arguments by checking esp before and after the call.
 297       </para>
 298
 299       <para>
 300         The main problem with this scheme is that the function must actually
 301         be called from another program. Many of these functions are seldom
 302         used. An attempt was made to aggressively query each function in a
 303         given library (<filename>ntdll.dll</filename>) by passing 64 arguments,
 304         all 0, to each function. Unfortunately, Windows NT quickly goes to a
 305         blue screen of death, even if the program is run from a
 306         non-administrator account.
 307       </para>
 308
 309       <para>
 310         Another method that has been much more successful is to attempt to
 311         figure out how many arguments each function is removing from the
 312         stack. This instruction, <literal>ret hhll</literal> (where
 313         <symbol>hhll</symbol> is the number of bytes to remove, i.e. the
 314         number of arguments times 4), contains the bytes
 315         <literal>0xc2 ll hh</literal> in memory. It is a reasonable
 316         assumption that few, if any, functions take more than 16 arguments;
 317         therefore, simply searching for
 318         <literal>hh == 0 && ll &lt; 0x40</literal>  starting from the
 319         address of a function yields the correct number of arguments most
 320         of the time.
 321       </para>
 322
 323       <para>
 324         Of course, this is not without errors. <literal>ret 00ll</literal>
 325         is not the only instruction that can have the byte sequence
 326         <literal>0xc2 ll 0x0</literal>; for example,
 327         <literal>push 0x000040c2</literal> has the byte sequence
 328         <literal>0x68 0xc2 0x40 0x0 0x0</literal>, which matches
 329         the above. Properly, the utility should look for this sequence
 330         only on an instruction boundary; unfortunately, finding
 331         instruction boundaries on an i386 requires implementing a full
 332         disassembler -- quite a daunting task. Besides, the probability
 333         of having such a byte sequence that is not the actual return
 334         instruction is fairly low.
 335       </para>
 336
 337       <para>
 338         Much more troublesome is the non-linear flow of a function. For
 339         example, consider the following two functions:
 340         <screen>
 341     somefunction1:
 342         jmp  somefunction1_impl
 343
 344     somefunction2:
 345         ret  0004
 346
 347     somefunction1_impl:
 348         ret  0008
 349         </screen>
 350         In this case, we would incorrectly detect both
 351         <function>somefunction1</function> and
 352         <function>somefunction2</function> as taking only a single
 353         argument, whereas <function>somefunction1</function> really
 354         takes two arguments.
 355       </para>
 356
 357       <para>
 358         With these limitations in mind, it is possible to implement
 359         more stubs
 360         in Wine and, eventually, the functions themselves.
 361       </para>
 362     </sect1>
 363     <sect1>
 364       <title>How to do regression testing using CVS</title>
 365
 366       <para>
 367         A problem that can happen sometimes is 'it used to work
 368         before, now it doesn't anymore...'. Here is a step by step
 369         procedure to try to pinpoint when the problem occurred. This
 370         is <emphasis>NOT</emphasis> for casual users.
 371       </para>
 372
 373       <orderedlist>
 374       <listitem>
 375           <para>
 376             Get the <quote>full CVS</quote> archive from winehq. This
 377             archive is the CVS tree but with the tags controlling the
 378             versioning system. It's a big file (> 40 meg) with a name
 379             like full-cvs-&lt;last update date> (it's more than 100mb
 380             when uncompressed, you can't very well do this with
 381             small, old computers or slow Internet connections).
 382           </para>
 383         </listitem>
 384         <listitem>
 385           <para>
 386             untar it into a repository directory:
 387             <screen>
 388 cd /home/gerard
 389 tar -zxf full-cvs-2003-08-18.tar.gz
 390 mv wine repository
 391             </screen>
 392           </para>
 393         </listitem>
 394         <listitem>
 395           <para>
 396             extract a new destination directory. This directory must
 397             not be in a subdirectory of the repository else
 398             <command>cvs</command> will think it's part of the
 399             repository and deny you an extraction in the repository:
 400             <screen>
 401 cd /home/gerard
 402 mv wine wine_current (-> this protects your current wine sandbox, if any)
 403 export CVSROOT=/home/gerard/repository
 404 cvs -d $CVSROOT checkout wine
 405             </screen>
 406           </para>
 407           <para>
 408             Note that it's not possible to do a checkout at a given
 409             date; you always do the checkout for the last date where
 410             the full-cvs-xxx snapshot was generated.
 411           </para>
 412           <para>
 413             Note also that it is possible to do all this with a direct
 414             CVS connection, of course. The full CVS file method is less
 415             painful for the WineHQ CVS server and probably a bit faster
 416             if you don't have a very good net connection.
 417           </para>
 418         </listitem>
 419         <listitem>
 420           <para>
 421             you will have now in the <filename>~/wine</filename>
 422             directory an image of the CVS tree, on the client side.
 423             Now update this image to the date you want:
 424             <screen>
 425 cd /home/gerard/wine
 426 cvs update -PAd -D "2004-08-23 CDT"
 427             </screen>
 428           </para>
 429           <para>
 430             The date format is <literal>YYYY-MM-DD HH:MM:SS</literal>.
 431             Using the CST date format ensure that you will be able to
 432             extract patches in a way that will be compatible with the
 433             wine-cvs archive
 434             <ulink url="http://www.winehq.org/hypermail/wine-cvs">
 435               http://www.winehq.org/hypermail/wine-cvs</ulink>
 436           </para>
 437           <para>
 438             Many messages will inform you that more recent files have
 439             been deleted to set back the client cvs tree to the date
 440             you asked, for example:
 441             <screen>
 442 cvs update: tsx11/ts_xf86dga2.c is no longer in the repository
 443             </screen>
 444           </para>
 445           <para>
 446             <command>cvs update</command> is not limited to upgrade to
 447             a <emphasis>newer</emphasis> version as I have believed for
 448             far too long :-(
 449           </para>
 450         </listitem>
 451         <listitem>
 452           <para>
 453             Now proceed as for a normal update:
 454           </para>
 455           <screen>
 456 ./configure
 457 make depend && make
 458           </screen>
 459           <para>
 460             If any non-programmer reads this, the fastest method to
 461             get at the point where the problem occurred is to use a
 462             binary search, that is, if the problem occurred in 1999,
 463             start at mid-year, then is the problem is already here,
 464             back to 1st April, if not, to 1st October, and so on.
 465           </para>
 466           <para>
 467             If you have lot of hard disk free space (a full compile
 468             currently takes 400 Mb), copy the oldest known working
 469             version before updating it, it will save time if you need
 470             to go back. (it's better to <command>make
 471               distclean</command> before going back in time, so you
 472             have to make everything if you don't backup the older
 473             version)
 474           </para>
 475           <para>
 476             When you have found the day where the problem happened,
 477             continue the search using the wine-cvs archive (sorted by
 478             date) and a more precise cvs update including hour,
 479             minute, second:
 480             <screen>
 481 cvs update -PAd -D "2004-08-23 15:17:25 CDT"
 482             </screen>
 483             This will allow you to find easily the exact patch that
 484             did it.
 485           </para>
 486         </listitem>
 487         <listitem>
 488           <para>
 489             If you find the patch that is the cause of the problem,
 490             you have almost won; report about it to
 491             <ulink url="http://bugs.winehq.org/">Wine Bugzilla</ulink>
 492             or subscribe to wine-devel and post it there. There is a
 493             chance that the author will jump in to suggest a fix; or
 494             there is always the possibility to look hard at the patch
 495             until it is coerced to reveal where is the bug :-)
 496           </para>
 497         </listitem>
 498       </orderedlist>
 499     </sect1>
 500
 501   </chapter>
 502
 503 <!-- Keep this comment at the end of the file
 504 Local variables:
 505 mode: sgml
 506 sgml-parent-document:("wine-devel.sgml" "set" "book" "part" "chapter" "")
 507 End:
 508 -->