devel/debug.xml

   1 <chapter id="debug">
   2 <chapterinfo>
   3         <author>
   4                 <firstname>Chris</firstname><surname>Hertel</surname>
   5         </author>
   6         <pubdate>July 1998</pubdate>
   7 </chapterinfo>
   8
   9 <title>The samba DEBUG system</title>
  10
  11 <sect1>
  12 <title>New Output Syntax</title>
  13
  14 <para>
  15    The syntax of a debugging log file is represented as:
  16 </para>
  17
  18 <para><programlisting>
  19   &gt;debugfile&lt; :== { &gt;debugmsg&lt; }
  20
  21   &gt;debugmsg&lt;  :== &gt;debughdr&lt; '\n' &gt;debugtext&lt;
  22
  23   &gt;debughdr&lt;  :== '[' TIME ',' LEVEL ']' FILE ':' [FUNCTION] '(' LINE ')'
  24
  25   &gt;debugtext&lt; :== { &gt;debugline&lt; }
  26
  27   &gt;debugline&lt; :== TEXT '\n'
  28 </programlisting></para>
  29
  30 <para>
  31 TEXT is a string of characters excluding the newline character.
  32 </para>
  33
  34 <para>
  35 LEVEL is the DEBUG level of the message (an integer in the range
  36                 0..10).
  37 </para>
  38
  39 <para>
  40 TIME is a timestamp.
  41 </para>
  42
  43 <para>
  44 FILE is the name of the file from which the debug message was
  45 generated.
  46 </para>
  47
  48 <para>
  49 FUNCTION is the function from which the debug message was generated.
  50 </para>
  51
  52 <para>
  53 LINE is the line number of the debug statement that generated the
  54 message.
  55 </para>
  56
  57 <para>Basically, what that all means is:</para>
  58 <orderedlist>
  59 <listitem><para>
  60 A debugging log file is made up of debug messages.
  61 </para></listitem>
  62 <listitem><para>
  63 Each debug message is made up of a header and text. The header is
  64 separated from the text by a newline.
  65 </para></listitem>
  66 <listitem><para>
  67 The header begins with the timestamp and debug level of the
  68 message enclosed in brackets. The filename, function, and line
  69 number at which the message was generated follow. The filename is
  70 terminated by a colon, and the function name is terminated by the
  71 parenthesis which contain the line number. Depending upon the
  72 compiler, the function name may be missing (it is generated by the
  73 __FUNCTION__ macro, which is not universally implemented, dangit).
  74 </para></listitem>
  75 <listitem><para>
  76 The message text is made up of zero or more lines, each terminated
  77 by a newline.
  78 </para></listitem>
  79 </orderedlist>
  80
  81 <para>Here's some example output:</para>
  82
  83 <para><programlisting>
  84     [1998/08/03 12:55:25, 1] nmbd.c:(659)
  85       Netbios nameserver version 1.9.19-prealpha started.
  86       Copyright Andrew Tridgell 1994-1997
  87     [1998/08/03 12:55:25, 3] loadparm.c:(763)
  88       Initializing global parameters
  89 </programlisting></para>
  90
  91 <para>
  92 Note that in the above example the function names are not listed on
  93 the header line. That's because the example above was generated on an
  94 SGI Indy, and the SGI compiler doesn't support the __FUNCTION__ macro.
  95 </para>
  96
  97 </sect1>
  98
  99 <sect1>
 100 <title>The DEBUG() Macro</title>
 101
 102 <para>
 103 Use of the DEBUG() macro is unchanged. DEBUG() takes two parameters.
 104 The first is the message level, the second is the body of a function
 105 call to the Debug1() function.
 106 </para>
 107
 108 <para>That's confusing.</para>
 109
 110 <para>Here's an example which may help a bit. If you would write</para>
 111
 112 <para><programlisting>
 113 printf( "This is a %s message.\n", "debug" );
 114 </programlisting></para>
 115
 116 <para>
 117 to send the output to stdout, then you would write
 118 </para>
 119
 120 <para><programlisting>
 121 DEBUG( 0, ( "This is a %s message.\n", "debug" ) );
 122 </programlisting></para>
 123
 124 <para>
 125 to send the output to the debug file.  All of the normal printf()
 126 formatting escapes work.
 127 </para>
 128
 129 <para>
 130 Note that in the above example the DEBUG message level is set to 0.
 131 Messages at level 0 always print.  Basically, if the message level is
 132 less than or equal to the global value DEBUGLEVEL, then the DEBUG
 133 statement is processed.
 134 </para>
 135
 136 <para>
 137 The output of the above example would be something like:
 138 </para>
 139
 140 <para><programlisting>
 141     [1998/07/30 16:00:51, 0] file.c:function(128)
 142       This is a debug message.
 143 </programlisting></para>
 144
 145 <para>
 146 Each call to DEBUG() creates a new header *unless* the output produced
 147 by the previous call to DEBUG() did not end with a '\n'. Output to the
 148 debug file is passed through a formatting buffer which is flushed
 149 every time a newline is encountered. If the buffer is not empty when
 150 DEBUG() is called, the new input is simply appended.
 151 </para>
 152
 153 <para>
 154 ...but that's really just a Kludge. It was put in place because
 155 DEBUG() has been used to write partial lines. Here's a simple (dumb)
 156 example of the kind of thing I'm talking about:
 157 </para>
 158
 159 <para><programlisting>
 160     DEBUG( 0, ("The test returned " ) );
 161     if( test() )
 162       DEBUG(0, ("True") );
 163     else
 164       DEBUG(0, ("False") );
 165     DEBUG(0, (".\n") );
 166 </programlisting></para>
 167
 168 <para>
 169 Without the format buffer, the output (assuming test() returned true)
 170 would look like this:
 171 </para>
 172
 173 <para><programlisting>
 174     [1998/07/30 16:00:51, 0] file.c:function(256)
 175       The test returned
 176     [1998/07/30 16:00:51, 0] file.c:function(258)
 177       True
 178     [1998/07/30 16:00:51, 0] file.c:function(261)
 179       .
 180 </programlisting></para>
 181
 182 <para>Which isn't much use. The format buffer kludge fixes this problem.
 183 </para>
 184
 185 </sect1>
 186
 187 <sect1>
 188 <title>The DEBUGADD() Macro</title>
 189
 190 <para>
 191 In addition to the kludgey solution to the broken line problem
 192 described above, there is a clean solution. The DEBUGADD() macro never
 193 generates a header. It will append new text to the current debug
 194 message even if the format buffer is empty. The syntax of the
 195 DEBUGADD() macro is the same as that of the DEBUG() macro.
 196 </para>
 197
 198 <para><programlisting>
 199     DEBUG( 0, ("This is the first line.\n" ) );
 200     DEBUGADD( 0, ("This is the second line.\nThis is the third line.\n" ) );
 201 </programlisting></para>
 202
 203 <para>Produces</para>
 204
 205 <para><programlisting>
 206     [1998/07/30 16:00:51, 0] file.c:function(512)
 207       This is the first line.
 208       This is the second line.
 209       This is the third line.
 210 </programlisting></para>
 211
 212 </sect1>
 213
 214 <sect1>
 215 <title>The DEBUGLVL() Macro</title>
 216
 217 <para>
 218 One of the problems with the DEBUG() macro was that DEBUG() lines
 219 tended to get a bit long. Consider this example from
 220 nmbd_sendannounce.c:
 221 </para>
 222
 223 <para><programlisting>
 224   DEBUG(3,("send_local_master_announcement: type %x for name %s on subnet %s for workgroup %s\n",
 225             type, global_myname, subrec->subnet_name, work->work_group));
 226 </programlisting></para>
 227
 228 <para>
 229 One solution to this is to break it down using DEBUG() and DEBUGADD(),
 230 as follows:
 231 </para>
 232
 233 <para><programlisting>
 234   DEBUG( 3, ( "send_local_master_announcement: " ) );
 235   DEBUGADD( 3, ( "type %x for name %s ", type, global_myname ) );
 236   DEBUGADD( 3, ( "on subnet %s ", subrec->subnet_name ) );
 237   DEBUGADD( 3, ( "for workgroup %s\n", work->work_group ) );
 238 </programlisting></para>
 239
 240 <para>
 241 A similar, but arguably nicer approach is to use the DEBUGLVL() macro.
 242 This macro returns True if the message level is less than or equal to
 243 the global DEBUGLEVEL value, so:
 244 </para>
 245
 246 <para><programlisting>
 247   if( DEBUGLVL( 3 ) )
 248     {
 249     dbgtext( "send_local_master_announcement: " );
 250     dbgtext( "type %x for name %s ", type, global_myname );
 251     dbgtext( "on subnet %s ", subrec->subnet_name );
 252     dbgtext( "for workgroup %s\n", work->work_group );
 253     }
 254 </programlisting></para>
 255
 256 <para>(The dbgtext() function is explained below.)</para>
 257
 258 <para>There are a few advantages to this scheme:</para>
 259 <orderedlist>
 260 <listitem><para>
 261 The test is performed only once.
 262 </para></listitem>
 263 <listitem><para>
 264 You can allocate variables off of the stack that will only be used
 265 within the DEBUGLVL() block.
 266 </para></listitem>
 267 <listitem><para>
 268 Processing that is only relevant to debug output can be contained
 269 within the DEBUGLVL() block.
 270 </para></listitem>
 271 </orderedlist>
 272
 273 </sect1>
 274
 275 <sect1>
 276 <title>New Functions</title>
 277
 278 <sect2>
 279 <title>dbgtext()</title>
 280 <para>
 281 This function prints debug message text to the debug file (and
 282 possibly to syslog) via the format buffer. The function uses a
 283 variable argument list just like printf() or Debug1(). The
 284 input is printed into a buffer using the vslprintf() function,
 285 and then passed to format_debug_text().
 286
 287 If you use DEBUGLVL() you will probably print the body of the
 288 message using dbgtext().
 289 </para>
 290 </sect2>
 291
 292 <sect2>
 293 <title>dbghdr()</title>
 294 <para>
 295 This is the function that writes a debug message header.
 296 Headers are not processed via the format buffer. Also note that
 297 if the format buffer is not empty, a call to dbghdr() will not
 298 produce any output. See the comments in dbghdr() for more info.
 299 </para>
 300
 301 <para>
 302 It is not likely that this function will be called directly. It
 303 is used by DEBUG() and DEBUGADD().
 304 </para>
 305 </sect2>
 306
 307 <sect2>
 308 <title>format_debug_text()</title>
 309 <para>
 310 This is a static function in debug.c. It stores the output text
 311 for the body of the message in a buffer until it encounters a
 312 newline. When the newline character is found, the buffer is
 313 written to the debug file via the Debug1() function, and the
 314 buffer is reset. This allows us to add the indentation at the
 315 beginning of each line of the message body, and also ensures
 316 that the output is written a line at a time (which cleans up
 317 syslog output).
 318 </para>
 319 </sect2>
 320 </sect1>
 321 </chapter>