4 <firstname>Chris</firstname><surname>Hertel</surname>
6 <pubdate>July 1998</pubdate>
9 <title>The samba DEBUG system</title>
12 <title>New Output Syntax</title>
15 The syntax of a debugging log file is represented as:
18 <para><programlisting>
19 >debugfile< :== { >debugmsg< }
21 >debugmsg< :== >debughdr< '\n' >debugtext<
23 >debughdr< :== '[' TIME ',' LEVEL ']' FILE ':' [FUNCTION] '(' LINE ')'
25 >debugtext< :== { >debugline< }
27 >debugline< :== TEXT '\n'
28 </programlisting></para>
31 TEXT is a string of characters excluding the newline character.
35 LEVEL is the DEBUG level of the message (an integer in the range
44 FILE is the name of the file from which the debug message was
49 FUNCTION is the function from which the debug message was generated.
53 LINE is the line number of the debug statement that generated the
57 <para>Basically, what that all means is:</para>
60 A debugging log file is made up of debug messages.
63 Each debug message is made up of a header and text. The header is
64 separated from the text by a newline.
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).
76 The message text is made up of zero or more lines, each terminated
81 <para>Here's some example output:</para>
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>
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.
100 <title>The DEBUG() Macro</title>
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.
108 <para>That's confusing.</para>
110 <para>Here's an example which may help a bit. If you would write</para>
112 <para><programlisting>
113 printf( "This is a %s message.\n", "debug" );
114 </programlisting></para>
117 to send the output to stdout, then you would write
120 <para><programlisting>
121 DEBUG( 0, ( "This is a %s message.\n", "debug" ) );
122 </programlisting></para>
125 to send the output to the debug file. All of the normal printf()
126 formatting escapes work.
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.
137 The output of the above example would be something like:
140 <para><programlisting>
141 [1998/07/30 16:00:51, 0] file.c:function(128)
142 This is a debug message.
143 </programlisting></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.
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:
159 <para><programlisting>
160 DEBUG( 0, ("The test returned " ) );
164 DEBUG(0, ("False") );
166 </programlisting></para>
169 Without the format buffer, the output (assuming test() returned true)
170 would look like this:
173 <para><programlisting>
174 [1998/07/30 16:00:51, 0] file.c:function(256)
176 [1998/07/30 16:00:51, 0] file.c:function(258)
178 [1998/07/30 16:00:51, 0] file.c:function(261)
180 </programlisting></para>
182 <para>Which isn't much use. The format buffer kludge fixes this problem.
188 <title>The DEBUGADD() Macro</title>
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.
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>
203 <para>Produces</para>
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>
215 <title>The DEBUGLVL() Macro</title>
218 One of the problems with the DEBUG() macro was that DEBUG() lines
219 tended to get a bit long. Consider this example from
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>
229 One solution to this is to break it down using DEBUG() and DEBUGADD(),
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>
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:
246 <para><programlisting>
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 );
254 </programlisting></para>
256 <para>(The dbgtext() function is explained below.)</para>
258 <para>There are a few advantages to this scheme:</para>
261 The test is performed only once.
264 You can allocate variables off of the stack that will only be used
265 within the DEBUGLVL() block.
268 Processing that is only relevant to debug output can be contained
269 within the DEBUGLVL() block.
276 <title>New Functions</title>
279 <title>dbgtext()</title>
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().
287 If you use DEBUGLVL() you will probably print the body of the
288 message using dbgtext().
293 <title>dbghdr()</title>
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.
302 It is not likely that this function will be called directly. It
303 is used by DEBUG() and DEBUGADD().
308 <title>format_debug_text()</title>
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