| <chapter id="debugging"> |
| <title>Debug Logging</title> |
| |
| <para> |
| Written by &name-dimitrie-paun; <email>&email-dimitrie-paun;</email>, 28 Mar 1998 |
| </para> |
| <para> |
| (Extracted from <filename>wine/documentation/debug-msgs</filename>) |
| </para> |
| |
| <note> |
| <para> |
| The new debugging interface can be considered to be |
| stable, with the exception of the in-memory message |
| construction functions. However, there is still a lot of |
| work to be done to polish things up. To make my life |
| easier, please follow the guidelines described in this |
| document. |
| </para> |
| |
| <para> |
| It is possible to turn on and of debugging output from |
| within the debuger using the set command. Please see the |
| WineDbg Command Reference section for how to do this. |
| </para> |
| </note> |
| |
| <important> |
| <para> |
| Read this document before writing new code. DO NOT USE |
| <function>fprintf</function> (or |
| <function>printf</function>) to output things. Also, instead |
| of writing FIXMEs in the source, output a FIXME message if |
| you can. |
| </para> |
| <para> |
| At the end of the document, there is a "Style Guide" for |
| debugging messages. Please read it. |
| </para> |
| </important> |
| |
| <sect1 id="dbg-classes"> |
| <title>Debugging classes</title> |
| |
| <para> |
| There are 4 types (or classes) of debugging messages: |
| </para> |
| <variablelist> |
| <varlistentry> |
| <term><literal>FIXME</literal></term> |
| <listitem> |
| <para> |
| Messages in this class relate to behavior of Wine that |
| does not correspond to standard Windows behavior and |
| that should be fixed. |
| </para> |
| <para>Examples: stubs, semi-implemented features, etc.</para> |
| </listitem> |
| </varlistentry> |
| <varlistentry> |
| <term><literal>ERR</literal></term> |
| <listitem> |
| <para> |
| Messages in this class relate to serious errors in |
| Wine. This sort of messages are close to asserts -- |
| that is, you should output an error message when the |
| code detects a condition which should not happen. In |
| other words, important things that are not warnings |
| (see below), are errors. |
| </para> |
| <para> |
| Examples: unexpected change in internal state, etc. |
| </para> |
| </listitem> |
| </varlistentry> |
| <varlistentry> |
| <term><literal>WARN</literal></term> |
| <listitem> |
| <para> |
| These are warning messages. You should report a |
| warning when something unwanted happen but the |
| function behaves properly. That is, output a warning |
| when you encounter something unexpected (ex: could not |
| open a file) but the function deals correctly with the |
| situation (that is, according to the docs). If you do |
| not deal correctly with it, output a fixme. |
| </para> |
| <para> |
| Examples: fail to access a resource required by the |
| app, etc. |
| </para> |
| </listitem> |
| </varlistentry> |
| <varlistentry> |
| <term><literal>TRACE</literal></term> |
| <listitem> |
| <para> |
| These are detailed debugging messages that are mainly |
| useful to debug a component. These are usually turned |
| off. |
| </para> |
| <para> |
| Examples: everything else that does not fall in one of |
| the above mentioned categories and the user does not |
| need to know about it. |
| </para> |
| </listitem> |
| </varlistentry> |
| </variablelist> |
| |
| <para> |
| The user has the capability to turn on or off messages of a |
| particular type. You can expect the following patterns of |
| usage (but note that any combination is possible): |
| </para> |
| <itemizedlist> |
| <listitem> |
| <para> |
| when you debug a component, all types |
| (<literal>TRACE</literal>, <literal>WARN</literal>, |
| <literal>ERR</literal>, <literal>FIXME</literal>) will |
| be enabled. |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| during the pre-alpha (maybe alpha) stage of Wine, most |
| likely the <literal>TRACE</literal> class will be |
| disabled by default, but all others |
| (<literal>WARN</literal>, <literal>ERR</literal>, |
| <literal>FIXME</literal>) will be enabled by default. |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| when Wine will become stable, most likely the |
| <literal>TRACE</literal> and <literal>WARN</literal> |
| classes will be disabled by default, but all |
| <literal>ERR</literal>s and <literal>FIXME</literal>s |
| will be enabled. |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| in some installations that want the smallest footprint |
| and where the debug information is of no interest, all |
| classes may be disabled by default. |
| </para> |
| </listitem> |
| </itemizedlist> |
| <para> |
| Of course, the user will have the runtime ability to |
| override these defaults. However, this ability may be turned |
| off and certain classes of messages may be completely |
| disabled at compile time to reduce the size of Wine. |
| </para> |
| </sect1> |
| |
| <sect1 id="dbg-channels"> |
| <title>Debugging channels</title> |
| |
| <para> |
| Also, we divide the debugging messages on a component basis. |
| Each component is assigned a debugging channel. The |
| identifier of the channel must be a valid C identifier but |
| note that it may also be a reserved word like |
| <type>int</type> or <type>static</type>. |
| </para> |
| <para> |
| Examples of debugging channels: |
| <simplelist type="inline"> |
| <member><literal>reg</literal></member> |
| <member><literal>updown</literal></member> |
| <member><literal>string</literal></member> |
| </simplelist> |
| </para> |
| <para> |
| We will refer to a generic channel as <literal>xxx</literal>. |
| </para> |
| <note> |
| <para> |
| for those who know the old interface, the channel/type is |
| what followed the _ in the |
| <function>dprintf_xxx</function> statements. For example, |
| to output a message on the debugging channel |
| <literal>reg</literal> in the old interface you would had |
| to write: |
| </para> |
| <programlisting> |
| dprintf_reg(stddeb, "Could not access key!\n"); |
| </programlisting> |
| <para> |
| In the new interface, we drop the |
| <literal>stddeb</literal> as it is implicit. However, we |
| add an orthogonal piece of information to the message: its |
| class. This is very important as it will allow us to |
| selectively turn on or off certain messages based on the |
| type of information they report. For this reason it is |
| essential to choose the right class for the message. |
| Anyhow, suppose we figured that this message should belong |
| in the <literal>WARN</literal> class, so in the new |
| interface, you write: |
| </para> |
| <programlisting> |
| WARN(reg, "Could not access key!\n"); |
| </programlisting> |
| </note> |
| </sect1> |
| |
| <sect1 id="dbg-using"> |
| <title>How to use it</title> |
| |
| <para> |
| So, to output a message (class <literal>YYY</literal>) on |
| channel <literal>xxx</literal>, do: |
| </para> |
| <programlisting> |
| #include "debugtools.h" |
| |
| .... |
| |
| YYY(xxx, "<message>", ...); |
| </programlisting> |
| <para> |
| Some examples from the code: |
| </para> |
| <programlisting> |
| #include "debugtools.h" |
| |
| ... |
| |
| TRACE(crtdll, "CRTDLL_setbuf(file %p buf %p)", file, buf); |
| |
| WARN(aspi, "Error opening device errno=%d", save_error); |
| </programlisting> |
| <para> |
| If you need to declare a new debugging channel, use it in |
| your code and then do: |
| </para> |
| <screen> |
| %tools/make_debug |
| </screen> |
| <para> |
| in the root directory of Wine. Note that this will result in |
| almost complete recompilation of Wine. |
| </para> |
| |
| <note> |
| <orderedlist> |
| <listitem> |
| <para> |
| Please pay attention to which class you assign the |
| message. There are only 4 classes, so it is not hard. |
| The reason it is important to get it right is that too |
| much information is no information. For example, if |
| you put things into the <literal>WARN</literal> class |
| that should really be in the <literal>TRACE</literal> |
| class, the output will be too big and this will force |
| the user to turn warnings off. But this way he will |
| fail to see the important ones. Also, if you put |
| warnings into the <literal>TRACE</literal> class lets |
| say, he will most likely miss those because usually |
| the <literal>TRACE</literal> class is turned off. A |
| similar argument can be made if you mix any other two |
| classes. |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| All lines should end with a newline. If you can NOT |
| output everything that you want in the line with only |
| one statement, then you need to build the string in |
| memory. Please read the section below "In-memory |
| messages" on the preferred way to do it. PLEASE USE |
| THAT INTERFACE TO BUILD MESSAGES IN MEMORY. The reason |
| is that we are not sure that we like it and having |
| everything in one format will facilitate the |
| (automatic) translation to a better interface. |
| </para> |
| </listitem> |
| </orderedlist> |
| </note> |
| </sect1> |
| |
| <sect1 id="dbg-checking"> |
| <title>Are we debugging?</title> |
| |
| <para> |
| To test whether the debugging output of class |
| <literal>yyy</literal> on channel <literal>xxx</literal> is |
| enabled, use: |
| </para> |
| <screen> |
| TRACE_ON to test if TRACE is enabled |
| WARN_ON to test if WARN is enabled |
| FIXME_ON to test if FIXME is enabled |
| ERR_ON to test if ERR is enabled |
| </screen> |
| <para> |
| Examples: |
| </para> |
| <programlisting> |
| if(TRACE_ON(atom)){ |
| ...blah... |
| } |
| </programlisting> |
| |
| <note> |
| <para> |
| You should normally need to test only if |
| <literal>TRACE_ON</literal>. At present, none of the other |
| 3 tests (except for <literal>ERR_ON</literal> which is |
| used only once!) are used in Wine. |
| </para> |
| </note> |
| </sect1> |
| |
| <sect1 id="dbg-in-memory"> |
| <title>In-memory messages</title> |
| |
| <para> |
| If you NEED to build the message from multiple calls, you |
| need to build it in memory. To do that, you should use the |
| following interface: |
| </para> |
| |
| <orderedlist> |
| <listitem> |
| <para> |
| declare a string (where you are allowed to declare C |
| variables) as follows: |
| <programlisting> |
| dbg_decl_str(name, len); |
| </programlisting> |
| where <parameter>name</parameter> is the name of the |
| string (you should use the channel name on which you |
| are going to output it) |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| print in it with: |
| <programlisting> |
| dsprintf(name, "<message>", ...); |
| </programlisting> |
| which is just like a <function>sprintf</function> |
| function but instead of a C string as first parameter it |
| takes the name you used to declare it. |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| obtain a pointer to the string with: <function>dbg_str(name)</function> |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| reset the string (if you want to reuse it with): |
| <programlisting> |
| dbg_reset_str(name); |
| </programlisting> |
| </para> |
| </listitem> |
| </orderedlist> |
| |
| <para> |
| Example (modified from the code): |
| </para> |
| <programlisting> |
| void some_func(tabs) |
| { |
| INT32 i; |
| LPINT16 p = (LPINT16)tabs; |
| dbg_decl_str(listbox, 256); /* declare the string */ |
| |
| for (i = 0; i < descr->nb_tabs; i++) { |
| descr->tabs[i] = *p++<<1; |
| if(TRACING(listbox)) /* write in it only if |
| dsprintf(listbox, "%hd ", descr->tabs[i]); /* we are gonna output it */ |
| } |
| TRACE(listbox, "Listbox %04x: settabstops %s", |
| wnd->hwndSelf, dbg_str(listbox)); /* output the whole thing */ |
| } |
| </programlisting> |
| <para> |
| If you need to use it two times in the same scope do like |
| this: |
| </para> |
| <programlisting> |
| void some_func(tabs) |
| { |
| INT32 i; |
| LPINT16 p = (LPINT16)tabs; |
| dbg_decl_str(listbox, 256); /* declare the string */ |
| |
| for (i = 0; i < descr->nb_tabs; i++) { |
| descr->tabs[i] = *p++<<1; |
| if(TRACING(listbox)) /* write in it only if |
| dsprintf(listbox, "%hd ", descr->tabs[i]); /* we are gonna output it */ |
| } |
| TRACE(listbox, "Listbox %04x: settabstops %s\n", |
| wnd->hwndSelf, dbg_str(listbox)); /* output the whole thing */ |
| |
| dbg_reset_str(listbox); /* !!!reset the string!!! */ |
| for (i = 0; i < descr->extrainfo_nr; i++) { |
| descr->extrainfo = *p+1; |
| if(TRACING(listbox)) /* write in it only if |
| dsprintf(listbox,"%3d ",descr->extrainfo); /* we are gonna output it */ |
| } |
| |
| TRACE(listbox, "Listbox %04x: extrainfo %s\n", |
| wnd->hwndSelf, dbg_str(listbox)); /* output the whole thing */ |
| |
| } |
| </programlisting> |
| |
| <important> |
| <para> |
| As I already stated, I do not think this will be the |
| ultimate interface for building in-memory debugging |
| messages. In fact, I do have better ideas which I hope to |
| have time to implement for the next release. For this |
| reason, please try not to use it. However, if you need to |
| output a line in more than one |
| <function>dprintf_xxx</function> calls, then USE THIS |
| INTERFACE. DO NOT use other methods. This way, I will |
| easily translate everything to the new interface (when it |
| will become available). So, if you need to use it, then |
| follow the following guidelines: |
| </para> |
| <itemizedlist> |
| <listitem> |
| <para>wrap calls to <function>dsprintf</function> with a |
| </para> |
| <programlisting> |
| if(YYY(xxx)) |
| dsprintf(xxx,...); |
| </programlisting> |
| <para> |
| Of course, if the call to |
| <function>dsprintf</function> is made from within a |
| function which you know is called only if |
| <function>YYY(xxx)</function> is true, for example if |
| you call it only like this: |
| </para> |
| <programlisting> |
| if(YYY(xxx)) |
| print_some_debug_info(); |
| </programlisting> |
| <para> |
| then you need not (and should not) wrap calls to |
| <function>dsprintf</function> with the before |
| mentioned <function>if</function>. |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| name the string EXACTLY like the debugging channel on |
| which is going to be output. Please see the above |
| example. |
| </para> |
| </listitem> |
| </itemizedlist> |
| </important> |
| </sect1> |
| |
| <sect1 id="dbg-resource-ids"> |
| <title>Resource identifiers</title> |
| |
| <para> |
| Resource identifiers can be either strings or numbers. To |
| make life a bit easier for outputting these beasts (and to |
| help you avoid the need to build the message in memory), I |
| introduced a new function called <function>debugres</function>. |
| </para> |
| <para> |
| The function is defined in <filename>debugstr.h</filename> |
| and has the following prototype: |
| </para> |
| <programlisting> |
| LPSTR debugres(const void *id); |
| </programlisting> |
| <para> |
| It takes a pointer to the resource id and returns a nicely |
| formatted string of the identifier. If the high word of the |
| pointer is <literal>0</literal>, then it assumes that the |
| identifier is a number and thus returns a string of the |
| form: |
| </para> |
| <programlisting> |
| #xxxx |
| </programlisting> |
| <para> |
| where <literal>xxxx</literal> are 4 hex-digits representing |
| the low word of <parameter>id</parameter>. |
| </para> |
| <para> |
| If the high word of the pointer is not <literal>0</literal>, |
| then it assumes that the identifier is a string and thus |
| returns a string of the form: |
| </para> |
| <programlisting> |
| '<identifier>' |
| </programlisting> |
| <para> |
| Thus, to use it, do something on the following lines: |
| </para> |
| <programlisting> |
| #include "debugtools.h" |
| |
| ... |
| |
| YYY(xxx, "resource is %s", debugres(myresource)); |
| </programlisting> |
| </sect1> |
| |
| <sect1 id="dbg-param"> |
| <title>The <parameter>--debugmsg</parameter> command line option</title> |
| |
| <para> |
| So, the <parameter>--debugmsg</parameter> command line |
| option has been changed as follows: |
| </para> |
| <itemizedlist> |
| <listitem> |
| <para> |
| the new syntax is: <parameter>--debugmsg |
| [yyy]#xxx[,[yyy1]#xxx1]*</parameter> where |
| <literal>#</literal> is either <literal>+</literal> or |
| <literal>-</literal> |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| when the optional class argument (<literal>yyy</literal>) |
| is not present, then the statement will |
| enable(<literal>+</literal>)/disable(<literal>-</literal>) |
| all messages for the given channel (<literal>xxx</literal>) |
| on all classes. For example: |
| </para> |
| <programlisting> |
| --debugmsg +reg,-file |
| </programlisting> |
| <para> |
| enables all messages on the <literal>reg</literal> |
| channel and disables all messages on the |
| <literal>file</literal> channel. This is same as the old |
| semantics. |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| when the optional class argument (<literal>yyy</literal>) |
| is present, then the statement will enable |
| (<literal>+</literal>)/disable(<literal>-</literal>) |
| messages for the given channel (<literal>xxx</literal>) |
| only on the given class. For example: |
| </para> |
| <programlisting> |
| --debugmsg trace+reg,warn-file |
| </programlisting> |
| <para> |
| enables trace messages on the <literal>reg</literal> |
| channel and disables warning messages on the |
| <literal>file</literal> channel. |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| also, the pseudo-channel all is also supported and it |
| has the intuitive semantics: |
| </para> |
| <screen> |
| --debugmsg +all -- enables all debug messages |
| --debugmsg -all -- disables all debug messages |
| --debugmsg yyy+all -- enables debug messages for class yyy on all |
| channels. |
| --debugmsg yyy-all -- disables debug messages for class yyy on all |
| channels. |
| </screen> |
| <para> |
| So, for example: |
| </para> |
| <screen> |
| --debugmsg warn-all -- disables all warning messages. |
| </screen> |
| </listitem> |
| </itemizedlist> |
| |
| <para> |
| Also, note that at the moment: |
| </para> |
| <itemizedlist> |
| <listitem> |
| <para>the <literal>FIXME</literal> and <literal>ERR</literal> |
| classes are enabled by default</para> |
| </listitem> |
| <listitem> |
| <para>the <literal>TRACE</literal> and |
| <literal>WARN</literal> classes are disabled by |
| default</para> |
| </listitem> |
| </itemizedlist> |
| </sect1> |
| |
| <sect1 id="dbg-compiling"> |
| <title>Compiling Out Debugging Messages</title> |
| |
| <para> |
| To compile out the debugging messages, provide |
| <command>configure</command> with the following options: |
| </para> |
| <screen> |
| --disable-debug -- turns off TRACE, WARN, and FIXME (and DUMP). |
| --disable-trace -- turns off TRACE only. |
| </screen> |
| <para> |
| This will result in an executable that, when stripped, is |
| about 15%-20% smaller. Note, however, that you will not be |
| able to effectively debug Wine without these messages. |
| </para> |
| <para> |
| This feature has not been extensively tested--it may subtly |
| break some things. |
| </para> |
| </sect1> |
| |
| <sect1 id="dbg-notes"> |
| <title>A Few Notes on Style</title> |
| |
| <para> |
| This new scheme makes certain things more consistent but |
| there is still room for improvement by using a common style |
| of debug messages. Before I continue, let me note that the |
| output format is the following: |
| </para> |
| <screen> |
| yyy:xxx:fff <message> |
| |
| where: |
| yyy = the class (fixme, err, warn, trace) |
| xxx = the channel (atom, win, font, etc) |
| fff = the function name |
| </screen> |
| <para> |
| these fields are output automatically. All you have to |
| provide is the <message> part. |
| </para> |
| <para> |
| So here are some ideas: |
| </para> |
| |
| <itemizedlist> |
| <listitem> |
| <para>do NOT include the name of the function: it is included automatically</para> |
| </listitem> |
| <listitem> |
| <para> |
| if you want to output the parameters of the function, do |
| it as the first thing and include them in parentheses, |
| like this: |
| <programlisting> |
| YYY(xxx, "(%d,%p,etc)...\n", par1, par2, ...); |
| </programlisting> |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| for stubs, you should output a <literal>FIXME</literal> |
| message. I suggest this style: |
| <programlisting> |
| FIXME(xxx, "(%x,%d...): stub\n", par1, par2, ...); |
| </programlisting> |
| That is, you output the parameters, then a : and then a string |
| containing the word "stub". I've seen "empty stub", and others, but I |
| think that just "stub" suffices. |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| output 1 and ONLY 1 line per message. That is, the format |
| string should contain only 1 <literal>\n</literal> and it |
| should always appear at the end of the string. (there are |
| many reasons for this requirement, one of them is that |
| each debug macro adds things to the beginning of the line) |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| if you want to name a value, use <literal>=</literal> and |
| NOT <literal>:</literal>. That is, instead of saying: |
| <programlisting> |
| FIXME(xxx, "(fd: %d, file: %s): stub\n", fd, name); |
| </programlisting> |
| say: |
| <programlisting> |
| FIXME(xxx, "(fd=%d, file=%s): stub\n", fd, name); |
| </programlisting> |
| use <literal>:</literal> to separate categories. |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| try to avoid the style: |
| <programlisting> |
| FIXME(xxx, "(fd=%d, file=%s)\n", fd, name); |
| </programlisting> |
| but use: |
| <programlisting> |
| FIXME(xxx, "(fd=%d, file=%s): stub\n", fd, name); |
| </programlisting> |
| The reason is that if you want to <command>grep</command> |
| for things, you would search for <literal>FIXME</literal> |
| but in the first case there is no additional information |
| available, where in the second one, there is (e.g. the word |
| stub) |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| if you output a string s that might contain control |
| characters, or if <parameter>s</parameter> may be |
| <literal>NULL</literal>, use |
| <function>debugstr_a</function> (for ASCII strings, or |
| <function>debugstr_w</function> for Unicode strings) to |
| convert <parameter>s</parameter> to a C string, like this: |
| <programlisting> |
| HANDLE32 WINAPI YourFunc(LPCSTR s) |
| { |
| FIXME(xxx, "(%s): stub\n", debugstr_a(s)); |
| } |
| </programlisting> |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| if you want to output a resource identifier, use debugres to |
| convert it to a string first, like this: |
| <programlisting> |
| HANDLE32 WINAPI YourFunc(LPCSTR res) |
| { |
| FIXME(xxx, "(res=%s): stub\n", debugres(s)); |
| } |
| </programlisting> |
| if the resource identifier is a <type>SEGPTR</type>, use |
| <function>PTR_SEG_TO_LIN</function> to get a |
| liner pointer first: |
| <programlisting> |
| HRSRC16 WINAPI FindResource16( HMODULE16 hModule, SEGPTR name, SEGPTR type ) |
| { |
| [...] |
| TRACE(resource, "module=%04x name=%s type=%s\n", |
| hModule, debugres(PTR_SEG_TO_LIN(name)), |
| debugres(PTR_SEG_TO_LIN(type)) ); |
| [...] |
| } |
| </programlisting> |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| for messages intended for the user (specifically those that |
| report errors in the wine config file), use the |
| <literal>MSG</literal> macro. Use it like a |
| <function>printf</function>: |
| <programlisting> |
| MSG( "Definition of drive %d is incorrect!\n", drive ); |
| </programlisting> |
| However, note that there are <emphasis>very</emphasis> few |
| valid uses of this macro. Most messages are debugging |
| messages, so chances are you will not need to use this |
| macro. Grep the source to get an idea where it is |
| appropriate to use it. |
| </para> |
| </listitem> |
| <listitem> |
| <para> |
| For structure dumps, use the <function>DUMP</function> |
| macro. Use it like a <function>printf</function>, just like |
| the <literal>MSG</literal> macro. Similarly, there are only |
| a few valid uses of this macro. Grep the source to see when |
| to use it. |
| </para> |
| </listitem> |
| </itemizedlist> |
| </sect1> |
| |
| </chapter> |
| |
| <!-- Keep this comment at the end of the file |
| Local variables: |
| mode: sgml |
| sgml-parent-document:("wine-doc.sgml" "set" "book" "part" "chapter" "") |
| End: |
| --> |