48 was plain wrong as value for HELmargin.
[wine] / documentation / debugging.sgml
1   <chapter id="debugging">
2     <title>Debug Logging</title>
3
4       <para>
5         Written by &name-dimitrie-paun; <email>&email-dimitrie-paun;</email>, 28 Mar 1998
6       </para>
7       <para>
8         (Extracted from <filename>wine/documentation/debug-msgs</filename>)
9       </para>
10
11       <note>
12         <para>
13           The new debugging interface can be considered to be
14           stable, with the exception of the in-memory message
15           construction functions. However, there is still a lot of
16           work to be done to polish things up. To make my life
17           easier, please follow the guidelines described in this
18           document.
19         </para>
20
21         <para>
22           It is possible to turn on and of debugging output from
23           within the debuger using the set command. Please see the
24           WineDbg Command Reference section for how to do this.
25         </para>
26       </note>
27
28       <important>
29         <para>
30           Read this document before writing new code. DO NOT USE
31           <function>fprintf</function>  (or
32           <function>printf</function>) to output things. Also, instead
33           of writing  FIXMEs in the source, output a FIXME message if
34           you can.
35         </para>
36         <para>
37           At the end of the document, there is a "Style Guide" for
38           debugging messages. Please read it.
39         </para>
40       </important>
41
42       <sect1 id="dbg-classes">
43         <title>Debugging classes</title>
44
45         <para>
46           There are 4 types (or classes) of debugging messages:
47         </para>
48         <variablelist>
49           <varlistentry>
50             <term><literal>FIXME</literal></term>
51             <listitem>
52               <para>
53                 Messages in this class relate to behavior of Wine that
54                 does not correspond to standard Windows behavior and
55                 that should be fixed.
56               </para>
57               <para>Examples: stubs, semi-implemented features, etc.</para>
58             </listitem>
59           </varlistentry>
60           <varlistentry>
61             <term><literal>ERR</literal></term>
62             <listitem>
63               <para>
64                 Messages in this class relate to serious errors in
65                 Wine. This sort of messages are close to asserts --
66                 that is, you should output an error message when the
67                 code detects a condition which should not happen. In
68                 other words, important things that are not warnings
69                 (see below), are errors.
70               </para>
71               <para>
72                 Examples: unexpected change in internal state, etc.
73               </para>
74             </listitem>
75           </varlistentry>
76           <varlistentry>
77             <term><literal>WARN</literal></term>
78             <listitem>
79               <para>
80                 These are warning messages. You should report a
81                 warning when something unwanted happen but the
82                 function behaves properly. That is, output a warning
83                 when you encounter something unexpected (ex: could not
84                 open a file) but the function deals correctly with the
85                 situation (that is, according to the docs). If you do
86                 not deal correctly with it, output a fixme.
87               </para>
88               <para>
89                 Examples: fail to access a resource required by the
90                 app, etc.
91               </para>
92             </listitem>
93           </varlistentry>
94           <varlistentry>
95             <term><literal>TRACE</literal></term>
96             <listitem>
97               <para>
98                 These are detailed debugging messages that are mainly
99                 useful  to debug a component. These are usually turned
100                 off.
101               </para>
102               <para>
103                 Examples: everything else that does not fall in one of
104                 the above mentioned categories and the user does not
105                 need to know about it.
106               </para>
107             </listitem>
108           </varlistentry>
109         </variablelist>
110
111         <para>
112           The user has the capability to turn on or off messages of a
113           particular type. You can expect the following patterns of
114           usage (but note that  any combination is possible):
115         </para>
116         <itemizedlist>
117           <listitem>
118             <para>
119               when you debug a component, all types
120               (<literal>TRACE</literal>, <literal>WARN</literal>,
121               <literal>ERR</literal>, <literal>FIXME</literal>) will
122               be enabled.
123             </para>
124           </listitem>
125           <listitem>
126             <para>
127               during the pre-alpha (maybe alpha) stage of Wine, most
128               likely the <literal>TRACE</literal> class will be
129               disabled by default, but all others
130               (<literal>WARN</literal>, <literal>ERR</literal>,
131               <literal>FIXME</literal>) will be enabled by default.
132             </para>
133           </listitem>
134           <listitem>
135             <para>
136               when Wine will become stable, most likely the
137               <literal>TRACE</literal> and <literal>WARN</literal>
138               classes will be disabled by default, but all
139               <literal>ERR</literal>s and <literal>FIXME</literal>s
140               will be enabled.
141             </para>
142           </listitem>
143           <listitem>
144             <para>
145               in some installations that want the smallest footprint
146               and where the debug information is of no interest,  all
147               classes may be disabled by default.
148             </para>
149           </listitem>
150         </itemizedlist>
151         <para>
152           Of course, the user will have the runtime ability to
153           override these defaults. However, this ability may be turned
154           off and certain classes of messages may be completely
155           disabled at compile time to reduce the  size of Wine.
156         </para>
157       </sect1>
158
159       <sect1 id="dbg-channels">
160         <title>Debugging channels</title>
161
162         <para>
163           Also, we divide the debugging messages on a component basis.
164           Each component is assigned a debugging channel. The
165           identifier of the channel must be a valid C identifier but
166           note that it may also be a reserved word like
167           <type>int</type> or <type>static</type>.
168         </para>
169         <para>
170           Examples of debugging channels:
171           <simplelist type="inline">
172             <member><literal>reg</literal></member>
173             <member><literal>updown</literal></member>
174             <member><literal>string</literal></member>
175           </simplelist>
176         </para>
177         <para>
178           We will refer to a generic channel as <literal>xxx</literal>.
179         </para>
180         <note>
181           <para>
182             for those who know the old interface, the channel/type is
183             what followed the _ in the
184             <function>dprintf_xxx</function> statements. For example,
185             to output a message on the debugging channel
186             <literal>reg</literal> in the old interface you would had
187             to write:
188           </para>
189           <programlisting>
190 dprintf_reg(stddeb, "Could not access key!\n");
191           </programlisting>
192           <para>
193             In the new interface, we drop the
194             <literal>stddeb</literal> as it is implicit. However, we
195             add an orthogonal piece of information to the message: its
196             class. This is very important as it will allow us to
197             selectively turn on or off certain messages based on the
198             type of information they report. For this reason it is
199             essential to choose the right class for the message.
200             Anyhow, suppose we figured that this message should belong
201             in the <literal>WARN</literal> class, so in the new
202             interface, you write:
203           </para>
204           <programlisting>
205 WARN(reg, "Could not access key!\n");
206           </programlisting>
207         </note>
208       </sect1>
209
210       <sect1 id="dbg-using">
211         <title>How to use it</title>
212
213         <para>
214           So, to output a message (class <literal>YYY</literal>) on
215           channel <literal>xxx</literal>, do:
216         </para>
217         <programlisting>
218 #include "debugtools.h"
219
220 ....
221
222 YYY(xxx, "&lt;message>", ...);
223         </programlisting>
224         <para>
225           Some examples from the code:
226         </para>
227         <programlisting>
228 #include "debugtools.h"
229
230 ...
231
232   TRACE(crtdll, "CRTDLL_setbuf(file %p buf %p)", file, buf);
233
234   WARN(aspi, "Error opening device errno=%d", save_error);
235         </programlisting>
236         <para>
237           If you need to declare a new debugging channel, use it in
238           your code and then do:
239         </para>
240         <screen>
241 %tools/make_debug
242         </screen>
243         <para>
244           in the root directory of Wine. Note that this will result in
245           almost complete recompilation of Wine.
246         </para>
247
248         <note>
249           <orderedlist>
250             <listitem>
251               <para>
252                 Please pay attention to which class you assign the
253                 message. There are only 4 classes, so it is not hard.
254                 The reason it is important to get it right is that too
255                 much information is no information. For example, if
256                 you put things into the <literal>WARN</literal> class
257                 that should really be in the <literal>TRACE</literal>
258                 class, the  output will be too big and this will force
259                 the user to  turn warnings off. But this way he will
260                 fail to see the important ones. Also, if you put
261                 warnings into the <literal>TRACE</literal> class lets
262                 say, he will most likely miss those because usually
263                 the <literal>TRACE</literal> class is turned off. A
264                 similar argument can be made if you mix any other two
265                 classes.
266               </para>
267             </listitem>
268             <listitem>
269               <para>
270                 All lines should end with a newline. If you can NOT
271                 output everything that you want in the line with only
272                 one statement, then you need to build the string in
273                 memory. Please read the section below "In-memory
274                 messages" on the preferred way to do it. PLEASE USE
275                 THAT INTERFACE TO BUILD MESSAGES IN MEMORY. The reason
276                 is that we are not sure that we like it and having
277                 everything in one format will facilitate the
278                 (automatic) translation to a better interface.
279               </para>
280             </listitem>
281           </orderedlist>
282         </note>
283       </sect1>
284
285       <sect1 id="dbg-checking">
286         <title>Are we debugging?</title>
287
288         <para>
289           To test whether the debugging output of class
290           <literal>yyy</literal> on channel <literal>xxx</literal> is
291           enabled, use:
292         </para>
293         <screen>
294 TRACE_ON  to test if TRACE is enabled
295 WARN_ON   to test if WARN is enabled
296 FIXME_ON  to test if FIXME is enabled
297 ERR_ON    to test if ERR is enabled
298         </screen>
299         <para>
300           Examples:
301         </para>
302         <programlisting>
303 if(TRACE_ON(atom)){
304   ...blah...
305 }
306         </programlisting>
307
308         <note>
309           <para>
310             You should normally need to test only if
311             <literal>TRACE_ON</literal>. At present, none of the other
312             3 tests (except for <literal>ERR_ON</literal> which is
313             used only once!) are used in Wine.
314           </para>
315         </note>
316       </sect1>
317
318       <sect1 id="dbg-in-memory">
319         <title>In-memory messages</title>
320
321         <para>
322           If you NEED to build the message from multiple calls, you
323           need to  build it in memory. To do that, you should use the
324           following interface:
325         </para>
326
327         <orderedlist>
328           <listitem>
329             <para>
330               declare a string (where you are allowed to declare C
331               variables) as follows:
332             <programlisting>
333 dbg_decl_str(name, len);
334             </programlisting>
335               where <parameter>name</parameter> is the name of the
336               string (you should use the channel name on which you
337               are going to output it)
338             </para>
339           </listitem>
340           <listitem>
341             <para>
342               print in it with:
343             <programlisting>
344 dsprintf(name, "&lt;message>", ...);
345             </programlisting>
346               which is just like a <function>sprintf</function>
347               function but instead of a C string as first parameter it
348               takes the name you used to declare it.
349             </para>
350           </listitem>
351           <listitem>
352             <para>
353               obtain a pointer to the string with: <function>dbg_str(name)</function>
354             </para>
355           </listitem>
356           <listitem>
357             <para>
358               reset the string (if you want to reuse it with):
359               <programlisting>
360 dbg_reset_str(name);
361               </programlisting>
362             </para>
363           </listitem>
364         </orderedlist>
365
366         <para>
367           Example (modified from the code):
368         </para>
369         <programlisting>
370 void some_func(tabs)
371 {
372   INT32 i;
373   LPINT16 p = (LPINT16)tabs;
374   dbg_decl_str(listbox, 256);                   /* declare the string */
375
376   for (i = 0; i &lt; descr->nb_tabs; i++) {
377     descr->tabs[i] = *p++&lt;&lt;1;
378     if(TRACING(listbox))                         /* write in it only if
379       dsprintf(listbox, "%hd ", descr->tabs[i]); /* we are gonna output it */
380   }
381   TRACE(listbox, "Listbox %04x: settabstops %s",
382         wnd->hwndSelf, dbg_str(listbox));        /* output the whole thing */
383 }
384         </programlisting>
385         <para>
386           If you need to use it two times in the same scope do like
387           this:
388         </para>
389         <programlisting>
390 void some_func(tabs)
391 {
392   INT32 i;
393   LPINT16 p = (LPINT16)tabs;
394   dbg_decl_str(listbox, 256);                   /* declare the string      */
395
396   for (i = 0; i &lt; descr->nb_tabs; i++) {
397     descr->tabs[i] = *p++&lt;&lt;1;
398     if(TRACING(listbox))                         /* write in it only if
399       dsprintf(listbox, "%hd ", descr->tabs[i]); /* we are gonna output it */
400   }
401   TRACE(listbox, "Listbox %04x: settabstops %s\n",
402         wnd->hwndSelf, dbg_str(listbox));        /* output the whole thing */
403
404   dbg_reset_str(listbox);                        /* !!!reset the string!!! */
405   for (i = 0; i &lt; descr->extrainfo_nr; i++) {
406     descr->extrainfo = *p+1;
407     if(TRACING(listbox))                         /* write in it only if
408       dsprintf(listbox,"%3d ",descr->extrainfo); /* we are gonna output it */
409   }
410
411   TRACE(listbox, "Listbox %04x: extrainfo %s\n",
412         wnd->hwndSelf, dbg_str(listbox));        /* output the whole thing */
413
414 }
415         </programlisting>
416
417         <important>
418           <para>
419             As I already stated, I do not think this will be the
420             ultimate interface for building in-memory debugging
421             messages. In fact, I do have better ideas which I hope to
422             have time to implement for the next release. For this
423             reason, please try not to use it. However, if you need to
424             output a line in more than one
425             <function>dprintf_xxx</function> calls, then USE THIS
426             INTERFACE. DO NOT use other methods. This way, I will
427             easily translate everything to the new interface (when it
428             will become available). So, if you need to use it, then
429             follow the following guidelines:
430           </para>
431           <itemizedlist>
432             <listitem>
433               <para>wrap calls to <function>dsprintf</function> with a
434               </para>
435               <programlisting>
436 if(YYY(xxx))
437   dsprintf(xxx,...);
438               </programlisting>
439               <para>
440                 Of course, if the call to
441                 <function>dsprintf</function> is made from within a
442                 function  which you know is called only if
443                 <function>YYY(xxx)</function> is true, for example if
444                 you call it only like this:
445               </para>
446               <programlisting>
447 if(YYY(xxx))
448   print_some_debug_info();
449               </programlisting>
450               <para>
451                 then you need not (and should not) wrap calls to
452                 <function>dsprintf</function> with the before
453                 mentioned <function>if</function>.
454               </para>
455             </listitem>
456             <listitem>
457               <para>
458                 name the string EXACTLY like the debugging channel on
459                 which is going to be output. Please see the above
460                 example.
461               </para>
462             </listitem>
463           </itemizedlist>
464         </important>
465       </sect1>
466
467       <sect1 id="dbg-resource-ids">
468         <title>Resource identifiers</title>
469
470         <para>
471           Resource identifiers can be either strings or numbers. To
472           make life a bit easier for outputting these beasts (and to
473           help you avoid the need to build the message in memory), I
474           introduced a new function called <function>debugres</function>.
475         </para>
476         <para>
477           The function is defined in <filename>debugstr.h</filename>
478           and has the following prototype:
479         </para>
480         <programlisting>
481 LPSTR debugres(const void *id);
482         </programlisting>
483         <para>
484           It takes a pointer to the resource id and returns a nicely
485           formatted string of the identifier. If the high word of the
486           pointer is <literal>0</literal>, then it assumes that the
487           identifier is a number and thus returns a string of the
488           form:
489         </para>
490         <programlisting>
491 #xxxx
492         </programlisting>
493         <para>
494           where <literal>xxxx</literal> are 4 hex-digits representing
495           the low word of <parameter>id</parameter>.
496         </para>
497         <para>
498           If the high word of the pointer is not <literal>0</literal>,
499           then it assumes that the identifier is a string and thus
500           returns a string of the form:
501         </para>
502         <programlisting>
503 '&lt;identifier>'
504         </programlisting>
505         <para>
506           Thus, to use it, do something on the following lines:
507         </para>
508         <programlisting>
509 #include "debugtools.h"
510
511 ...
512
513    YYY(xxx, "resource is %s", debugres(myresource));
514         </programlisting>
515       </sect1>
516
517       <sect1 id="dbg-param">
518         <title>The <parameter>--debugmsg</parameter> command line option</title>
519
520         <para>
521           So, the <parameter>--debugmsg</parameter> command line
522           option has been changed as follows:
523         </para>
524         <itemizedlist>
525           <listitem>
526             <para>
527               the new syntax is: <parameter>--debugmsg
528                 [yyy]#xxx[,[yyy1]#xxx1]*</parameter> where
529               <literal>#</literal> is either <literal>+</literal> or
530               <literal>-</literal>
531             </para>
532           </listitem>
533           <listitem>
534             <para>
535               when the optional class argument (<literal>yyy</literal>)
536               is not present, then the statement will
537               enable(<literal>+</literal>)/disable(<literal>-</literal>)
538               all messages for the given channel (<literal>xxx</literal>)
539               on all classes. For example:
540             </para>
541             <programlisting>
542 --debugmsg +reg,-file
543             </programlisting>
544             <para>
545               enables all messages on the <literal>reg</literal>
546               channel and disables all messages on the
547               <literal>file</literal> channel. This is same as the old
548               semantics.
549             </para>
550           </listitem>
551           <listitem>
552             <para>
553               when the optional class argument (<literal>yyy</literal>)
554               is present,  then the statement will enable
555               (<literal>+</literal>)/disable(<literal>-</literal>)
556               messages for the given channel (<literal>xxx</literal>)
557               only on the given class. For example:
558             </para>
559             <programlisting>
560 --debugmsg trace+reg,warn-file
561             </programlisting>
562             <para>
563               enables trace messages on the <literal>reg</literal>
564               channel and disables warning messages on the
565               <literal>file</literal> channel.
566             </para>
567           </listitem>
568           <listitem>
569             <para>
570               also, the pseudo-channel all is also supported and it
571               has the  intuitive semantics:
572             </para>
573             <screen>
574     --debugmsg +all      -- enables all debug messages
575     --debugmsg -all      -- disables all debug messages
576     --debugmsg yyy+all   -- enables debug messages for class yyy on all
577                            channels.
578     --debugmsg yyy-all   -- disables debug messages for class yyy on all
579                            channels.
580             </screen>
581             <para>
582               So, for example:
583             </para>
584             <screen>
585     --debugmsg warn-all  -- disables all warning messages.
586             </screen>
587           </listitem>
588         </itemizedlist>
589
590         <para>
591           Also, note that at the moment:
592         </para>
593         <itemizedlist>
594           <listitem>
595             <para>the <literal>FIXME</literal> and <literal>ERR</literal>
596               classes are enabled by default</para>
597           </listitem>
598           <listitem>
599             <para>the <literal>TRACE</literal> and
600               <literal>WARN</literal> classes are disabled by
601               default</para>
602           </listitem>
603         </itemizedlist>
604       </sect1>
605
606       <sect1 id="dbg-compiling">
607         <title>Compiling Out Debugging Messages</title>
608
609         <para>
610           To compile out the debugging messages, provide
611           <command>configure</command> with the following options:
612         </para>
613         <screen>
614     --disable-debug      -- turns off TRACE, WARN, and FIXME (and DUMP).
615     --disable-trace      -- turns off TRACE only.
616         </screen>
617         <para>
618           This will result in an executable that, when stripped, is
619           about 15%-20% smaller.  Note, however, that you will not be
620           able to effectively debug Wine without these messages.
621         </para>
622         <para>
623           This feature has not been extensively tested--it may subtly
624           break some things.
625         </para>
626       </sect1>
627
628       <sect1 id="dbg-notes">
629         <title>A Few Notes on Style</title>
630
631         <para>
632           This new scheme makes certain things more consistent but
633           there is still room for improvement by using a common style
634           of debug messages. Before I continue, let me note that the
635           output format is the following:
636         </para>
637         <screen>
638 yyy:xxx:fff &lt;message>
639
640 where:
641   yyy = the class (fixme, err, warn, trace)
642   xxx = the channel (atom, win, font, etc)
643   fff = the function name
644         </screen>
645         <para>
646           these fields are output automatically. All you have to
647           provide is the &lt;message> part.
648         </para>
649         <para>
650           So here are some ideas:
651         </para>
652
653         <itemizedlist>
654           <listitem>
655             <para>do NOT include the name of the function: it is included automatically</para>
656           </listitem>
657           <listitem>
658             <para>
659               if you want to output the parameters of the function, do
660               it as the first thing and include them in parentheses,
661               like this:
662               <programlisting>
663 YYY(xxx, "(%d,%p,etc)...\n", par1, par2, ...);
664               </programlisting>
665             </para>
666           </listitem>
667           <listitem>
668             <para>
669               for stubs, you should output a <literal>FIXME</literal>
670               message. I suggest this style:
671               <programlisting>
672    FIXME(xxx, "(%x,%d...): stub\n", par1, par2, ...);
673               </programlisting>
674               That is, you output the parameters, then a : and then a string
675               containing the word "stub". I've seen "empty stub", and others, but I
676               think that just "stub" suffices.
677             </para>
678           </listitem>
679           <listitem>
680             <para>
681               output 1 and ONLY 1 line per message. That is, the format
682               string should contain only 1 <literal>\n</literal> and it
683               should always appear at the end of the string. (there are
684               many reasons  for this requirement, one of them is that
685               each debug macro adds things to the beginning of the line)
686             </para>
687           </listitem>
688           <listitem>
689             <para>
690               if you want to name a value, use <literal>=</literal> and
691               NOT <literal>:</literal>. That is, instead of saying:
692               <programlisting>
693 FIXME(xxx, "(fd: %d, file: %s): stub\n", fd, name);
694               </programlisting>
695               say:
696               <programlisting>
697 FIXME(xxx, "(fd=%d, file=%s): stub\n", fd, name);
698               </programlisting>
699               use <literal>:</literal> to separate categories.
700             </para>
701           </listitem>
702           <listitem>
703             <para>
704               try to avoid the style:
705               <programlisting>
706 FIXME(xxx, "(fd=%d, file=%s)\n", fd, name);
707               </programlisting>
708               but use:
709               <programlisting>
710 FIXME(xxx, "(fd=%d, file=%s): stub\n", fd, name);
711               </programlisting>
712               The reason is that if you want to <command>grep</command>
713               for things, you would search for <literal>FIXME</literal>
714               but in the first case there is no additional information
715               available, where in the second one, there is (e.g. the word
716               stub)
717             </para>
718           </listitem>
719           <listitem>
720             <para>
721               if you output a string s that might contain control
722               characters, or if <parameter>s</parameter> may be
723               <literal>NULL</literal>, use
724               <function>debugstr_a</function> (for ASCII strings, or
725               <function>debugstr_w</function> for Unicode strings) to
726               convert <parameter>s</parameter> to a C string, like  this:
727               <programlisting>
728 HANDLE32 WINAPI YourFunc(LPCSTR s)
729 {
730     FIXME(xxx, "(%s): stub\n", debugstr_a(s));
731 }
732               </programlisting>
733             </para>
734           </listitem>
735           <listitem>
736             <para>
737               if you want to output a resource identifier, use debugres to
738               convert it to a string first, like this:
739               <programlisting>
740 HANDLE32 WINAPI YourFunc(LPCSTR res)
741 {
742     FIXME(xxx, "(res=%s): stub\n", debugres(s));
743 }
744               </programlisting>
745               if the resource identifier is a <type>SEGPTR</type>, use
746               <function>PTR_SEG_TO_LIN</function> to get a
747               liner pointer first:
748               <programlisting>
749 HRSRC16 WINAPI FindResource16( HMODULE16 hModule, SEGPTR name, SEGPTR type )
750 {
751 [...]
752     TRACE(resource, "module=%04x name=%s type=%s\n",
753                  hModule, debugres(PTR_SEG_TO_LIN(name)),
754                  debugres(PTR_SEG_TO_LIN(type)) );
755 [...]
756 }
757               </programlisting>
758             </para>
759           </listitem>
760           <listitem>
761             <para>
762               for messages intended for the user (specifically those that
763               report errors in <filename>wine.conf</filename>), use the
764               <literal>MSG</literal> macro. Use it like a
765               <function>printf</function>:
766               <programlisting>
767 MSG( "Definition of drive %d is incorrect!\n", drive );
768               </programlisting>
769               However, note that there are <emphasis>very</emphasis> few
770               valid uses of this macro. Most messages are debugging
771               messages, so chances are you will not need to use this
772               macro. Grep the source to get an idea where it is
773               appropriate to use it.
774             </para>
775           </listitem>
776           <listitem>
777             <para>
778               For structure dumps, use the <function>DUMP</function>
779               macro. Use it like a <function>printf</function>, just like
780               the <literal>MSG</literal> macro. Similarly, there are only
781               a few valid uses of this macro. Grep the source to see when
782               to use it.
783             </para>
784           </listitem>
785         </itemizedlist>
786       </sect1>
787
788   </chapter>
789
790 <!-- Keep this comment at the end of the file
791 Local variables:
792 mode: sgml
793 sgml-parent-document:("wine-doc.sgml" "set" "book" "part" "chapter" "")
794 End:
795 -->