1 <chapter id="debugging">
2 <title>Debug Logging</title>
5 Written by &name-dimitrie-paun; <email>&email-dimitrie-paun;</email>, 28 Mar 1998
8 (Extracted from <filename>wine/documentation/debug-msgs</filename>)
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
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.
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
37 At the end of the document, there is a "Style Guide" for
38 debugging messages. Please read it.
42 <sect1 id="dbg-classes">
43 <title>Debugging classes</title>
46 There are 4 types (or classes) of debugging messages:
50 <term><literal>FIXME</literal></term>
53 Messages in this class relate to behavior of Wine that
54 does not correspond to standard Windows behavior and
57 <para>Examples: stubs, semi-implemented features, etc.</para>
61 <term><literal>ERR</literal></term>
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.
72 Examples: unexpected change in internal state, etc.
77 <term><literal>WARN</literal></term>
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.
89 Examples: fail to access a resource required by the
95 <term><literal>TRACE</literal></term>
98 These are detailed debugging messages that are mainly
99 useful to debug a component. These are usually turned
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.
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):
119 when you debug a component, all types
120 (<literal>TRACE</literal>, <literal>WARN</literal>,
121 <literal>ERR</literal>, <literal>FIXME</literal>) will
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.
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
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.
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.
159 <sect1 id="dbg-channels">
160 <title>Debugging channels</title>
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>.
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>
178 We will refer to a generic channel as <literal>xxx</literal>.
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
190 dprintf_reg(stddeb, "Could not access key!\n");
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:
205 WARN(reg, "Could not access key!\n");
210 <sect1 id="dbg-using">
211 <title>How to use it</title>
214 So, to output a message (class <literal>YYY</literal>) on
215 channel <literal>xxx</literal>, do:
218 #include "debugtools.h"
222 YYY(xxx, "<message>", ...);
225 Some examples from the code:
228 #include "debugtools.h"
232 TRACE(crtdll, "CRTDLL_setbuf(file %p buf %p)", file, buf);
234 WARN(aspi, "Error opening device errno=%d", save_error);
237 If you need to declare a new debugging channel, use it in
238 your code and then do:
244 in the root directory of Wine. Note that this will result in
245 almost complete recompilation of Wine.
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
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.
285 <sect1 id="dbg-checking">
286 <title>Are we debugging?</title>
289 To test whether the debugging output of class
290 <literal>yyy</literal> on channel <literal>xxx</literal> is
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
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.
318 <sect1 id="dbg-in-memory">
319 <title>In-memory messages</title>
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
330 declare a string (where you are allowed to declare C
331 variables) as follows:
333 dbg_decl_str(name, len);
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)
344 dsprintf(name, "<message>", ...);
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.
353 obtain a pointer to the string with: <function>dbg_str(name)</function>
358 reset the string (if you want to reuse it with):
367 Example (modified from the code):
373 LPINT16 p = (LPINT16)tabs;
374 dbg_decl_str(listbox, 256); /* declare the string */
376 for (i = 0; i < descr->nb_tabs; i++) {
377 descr->tabs[i] = *p++<<1;
378 if(TRACING(listbox)) /* write in it only if
379 dsprintf(listbox, "%hd ", descr->tabs[i]); /* we are gonna output it */
381 TRACE(listbox, "Listbox %04x: settabstops %s",
382 wnd->hwndSelf, dbg_str(listbox)); /* output the whole thing */
386 If you need to use it two times in the same scope do like
393 LPINT16 p = (LPINT16)tabs;
394 dbg_decl_str(listbox, 256); /* declare the string */
396 for (i = 0; i < descr->nb_tabs; i++) {
397 descr->tabs[i] = *p++<<1;
398 if(TRACING(listbox)) /* write in it only if
399 dsprintf(listbox, "%hd ", descr->tabs[i]); /* we are gonna output it */
401 TRACE(listbox, "Listbox %04x: settabstops %s\n",
402 wnd->hwndSelf, dbg_str(listbox)); /* output the whole thing */
404 dbg_reset_str(listbox); /* !!!reset the string!!! */
405 for (i = 0; i < 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 */
411 TRACE(listbox, "Listbox %04x: extrainfo %s\n",
412 wnd->hwndSelf, dbg_str(listbox)); /* output the whole thing */
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:
433 <para>wrap calls to <function>dsprintf</function> with a
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:
448 print_some_debug_info();
451 then you need not (and should not) wrap calls to
452 <function>dsprintf</function> with the before
453 mentioned <function>if</function>.
458 name the string EXACTLY like the debugging channel on
459 which is going to be output. Please see the above
467 <sect1 id="dbg-resource-ids">
468 <title>Resource identifiers</title>
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>.
477 The function is defined in <filename>debugstr.h</filename>
478 and has the following prototype:
481 LPSTR debugres(const void *id);
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
494 where <literal>xxxx</literal> are 4 hex-digits representing
495 the low word of <parameter>id</parameter>.
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:
506 Thus, to use it, do something on the following lines:
509 #include "debugtools.h"
513 YYY(xxx, "resource is %s", debugres(myresource));
517 <sect1 id="dbg-param">
518 <title>The <parameter>--debugmsg</parameter> command line option</title>
521 So, the <parameter>--debugmsg</parameter> command line
522 option has been changed as follows:
527 the new syntax is: <parameter>--debugmsg
528 [yyy]#xxx[,[yyy1]#xxx1]*</parameter> where
529 <literal>#</literal> is either <literal>+</literal> or
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:
542 --debugmsg +reg,-file
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
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:
560 --debugmsg trace+reg,warn-file
563 enables trace messages on the <literal>reg</literal>
564 channel and disables warning messages on the
565 <literal>file</literal> channel.
570 also, the pseudo-channel all is also supported and it
571 has the intuitive semantics:
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
578 --debugmsg yyy-all -- disables debug messages for class yyy on all
585 --debugmsg warn-all -- disables all warning messages.
591 Also, note that at the moment:
595 <para>the <literal>FIXME</literal> and <literal>ERR</literal>
596 classes are enabled by default</para>
599 <para>the <literal>TRACE</literal> and
600 <literal>WARN</literal> classes are disabled by
606 <sect1 id="dbg-compiling">
607 <title>Compiling Out Debugging Messages</title>
610 To compile out the debugging messages, provide
611 <command>configure</command> with the following options:
614 --disable-debug -- turns off TRACE, WARN, and FIXME (and DUMP).
615 --disable-trace -- turns off TRACE only.
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.
623 This feature has not been extensively tested--it may subtly
628 <sect1 id="dbg-notes">
629 <title>A Few Notes on Style</title>
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:
638 yyy:xxx:fff <message>
641 yyy = the class (fixme, err, warn, trace)
642 xxx = the channel (atom, win, font, etc)
643 fff = the function name
646 these fields are output automatically. All you have to
647 provide is the <message> part.
650 So here are some ideas:
655 <para>do NOT include the name of the function: it is included automatically</para>
659 if you want to output the parameters of the function, do
660 it as the first thing and include them in parentheses,
663 YYY(xxx, "(%d,%p,etc)...\n", par1, par2, ...);
669 for stubs, you should output a <literal>FIXME</literal>
670 message. I suggest this style:
672 FIXME(xxx, "(%x,%d...): stub\n", par1, par2, ...);
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.
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)
690 if you want to name a value, use <literal>=</literal> and
691 NOT <literal>:</literal>. That is, instead of saying:
693 FIXME(xxx, "(fd: %d, file: %s): stub\n", fd, name);
697 FIXME(xxx, "(fd=%d, file=%s): stub\n", fd, name);
699 use <literal>:</literal> to separate categories.
704 try to avoid the style:
706 FIXME(xxx, "(fd=%d, file=%s)\n", fd, name);
710 FIXME(xxx, "(fd=%d, file=%s): stub\n", fd, name);
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
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:
728 HANDLE32 WINAPI YourFunc(LPCSTR s)
730 FIXME(xxx, "(%s): stub\n", debugstr_a(s));
737 if you want to output a resource identifier, use debugres to
738 convert it to a string first, like this:
740 HANDLE32 WINAPI YourFunc(LPCSTR res)
742 FIXME(xxx, "(res=%s): stub\n", debugres(s));
745 if the resource identifier is a <type>SEGPTR</type>, use
746 <function>PTR_SEG_TO_LIN</function> to get a
749 HRSRC16 WINAPI FindResource16( HMODULE16 hModule, SEGPTR name, SEGPTR type )
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)) );
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>:
767 MSG( "Definition of drive %d is incorrect!\n", drive );
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.
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
790 <!-- Keep this comment at the end of the file
793 sgml-parent-document:("wine-doc.sgml" "set" "book" "part" "chapter" "")