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