summaryrefslogtreecommitdiff
path: root/docs/docbook/devdoc/debug.sgml
blob: 7e81cc825db2b013d9e695458e9b8b48429a706e (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
<chapter id="debug">
<chapterinfo>
	<author>
		<firstname>Chris</firstname><surname>Hertel</surname>
	</author>
	<pubdate>July 1998</pubdate>
</chapterinfo>

<title>The samba DEBUG system</title>

<sect1>
<title>New Output Syntax</title>

<para>
   The syntax of a debugging log file is represented as:
</para>

<para><programlisting>
  &gt;debugfile&lt; :== { &gt;debugmsg&lt; }

  &gt;debugmsg&lt;  :== &gt;debughdr&lt; '\n' &gt;debugtext&lt;

  &gt;debughdr&lt;  :== '[' TIME ',' LEVEL ']' FILE ':' [FUNCTION] '(' LINE ')'

  &gt;debugtext&lt; :== { &gt;debugline&lt; }

  &gt;debugline&lt; :== TEXT '\n'
</programlisting></para>

<para>
TEXT is a string of characters excluding the newline character.
</para>

<para>
LEVEL is the DEBUG level of the message (an integer in the range
		0..10).
</para>

<para>
TIME is a timestamp.
</para>

<para>
FILE is the name of the file from which the debug message was
generated.
</para>

<para>
FUNCTION is the function from which the debug message was generated.
</para>

<para>
LINE is the line number of the debug statement that generated the
message.
</para>

<para>Basically, what that all means is:</para>
<orderedlist>
<listitem><para>
A debugging log file is made up of debug messages.
</para></listitem>
<listitem><para>
Each debug message is made up of a header and text. The header is
separated from the text by a newline.
</para></listitem>
<listitem><para>
The header begins with the timestamp and debug level of the
message enclosed in brackets. The filename, function, and line
number at which the message was generated follow. The filename is
terminated by a colon, and the function name is terminated by the
parenthesis which contain the line number. Depending upon the
compiler, the function name may be missing (it is generated by the
__FUNCTION__ macro, which is not universally implemented, dangit).
</para></listitem>
<listitem><para>
The message text is made up of zero or more lines, each terminated
by a newline.
</para></listitem>
</orderedlist>

<para>Here's some example output:</para>

<para><programlisting>
    [1998/08/03 12:55:25, 1] nmbd.c:(659)
      Netbios nameserver version 1.9.19-prealpha started.
      Copyright Andrew Tridgell 1994-1997
    [1998/08/03 12:55:25, 3] loadparm.c:(763)
      Initializing global parameters
</programlisting></para>

<para>
Note that in the above example the function names are not listed on
the header line. That's because the example above was generated on an
SGI Indy, and the SGI compiler doesn't support the __FUNCTION__ macro.
</para>

</sect1>

<sect1>
<title>The DEBUG() Macro</title>

<para>
Use of the DEBUG() macro is unchanged. DEBUG() takes two parameters.
The first is the message level, the second is the body of a function
call to the Debug1() function.
</para>

<para>That's confusing.</para>

<para>Here's an example which may help a bit. If you would write</para>

<para><programlisting>
printf( "This is a %s message.\n", "debug" );
</programlisting></para>

<para>
to send the output to stdout, then you would write
</para>

<para><programlisting>
DEBUG( 0, ( "This is a %s message.\n", "debug" ) );
</programlisting></para>

<para>
to send the output to the debug file.  All of the normal printf()
formatting escapes work.
</para>

<para>
Note that in the above example the DEBUG message level is set to 0.
Messages at level 0 always print.  Basically, if the message level is
less than or equal to the global value DEBUGLEVEL, then the DEBUG
statement is processed.
</para>

<para>
The output of the above example would be something like:
</para>

<para><programlisting>
    [1998/07/30 16:00:51, 0] file.c:function(128)
      This is a debug message.
</programlisting></para>

<para>
Each call to DEBUG() creates a new header *unless* the output produced
by the previous call to DEBUG() did not end with a '\n'. Output to the
debug file is passed through a formatting buffer which is flushed
every time a newline is encountered. If the buffer is not empty when
DEBUG() is called, the new input is simply appended.
</para>

<para>
...but that's really just a Kludge. It was put in place because
DEBUG() has been used to write partial lines. Here's a simple (dumb)
example of the kind of thing I'm talking about:
</para>

<para><programlisting>
    DEBUG( 0, ("The test returned " ) );
    if( test() )
      DEBUG(0, ("True") );
    else
      DEBUG(0, ("False") );
    DEBUG(0, (".\n") );
</programlisting></para>

<para>
Without the format buffer, the output (assuming test() returned true)
would look like this:
</para>

<para><programlisting>
    [1998/07/30 16:00:51, 0] file.c:function(256)
      The test returned
    [1998/07/30 16:00:51, 0] file.c:function(258)
      True
    [1998/07/30 16:00:51, 0] file.c:function(261)
      .
</programlisting></para>

<para>Which isn't much use. The format buffer kludge fixes this problem.
</para>

</sect1>

<sect1>
<title>The DEBUGADD() Macro</title>

<para>
In addition to the kludgey solution to the broken line problem
described above, there is a clean solution. The DEBUGADD() macro never
generates a header. It will append new text to the current debug
message even if the format buffer is empty. The syntax of the
DEBUGADD() macro is the same as that of the DEBUG() macro.
</para>

<para><programlisting>
    DEBUG( 0, ("This is the first line.\n" ) );
    DEBUGADD( 0, ("This is the second line.\nThis is the third line.\n" ) );
</programlisting></para>

<para>Produces</para>

<para><programlisting>
    [1998/07/30 16:00:51, 0] file.c:function(512)
      This is the first line.
      This is the second line.
      This is the third line.
</programlisting></para>

</sect1>

<sect1>
<title>The DEBUGLVL() Macro</title>

<para>
One of the problems with the DEBUG() macro was that DEBUG() lines
tended to get a bit long. Consider this example from
nmbd_sendannounce.c:
</para>

<para><programlisting>
  DEBUG(3,("send_local_master_announcement: type %x for name %s on subnet %s for workgroup %s\n",
            type, global_myname, subrec->subnet_name, work->work_group));
</programlisting></para>

<para>
One solution to this is to break it down using DEBUG() and DEBUGADD(),
as follows:
</para>

<para><programlisting>
  DEBUG( 3, ( "send_local_master_announcement: " ) );
  DEBUGADD( 3, ( "type %x for name %s ", type, global_myname ) );
  DEBUGADD( 3, ( "on subnet %s ", subrec->subnet_name ) );
  DEBUGADD( 3, ( "for workgroup %s\n", work->work_group ) );
</programlisting></para>

<para>
A similar, but arguably nicer approach is to use the DEBUGLVL() macro.
This macro returns True if the message level is less than or equal to
the global DEBUGLEVEL value, so:
</para>

<para><programlisting>
  if( DEBUGLVL( 3 ) )
    {
    dbgtext( "send_local_master_announcement: " );
    dbgtext( "type %x for name %s ", type, global_myname );
    dbgtext( "on subnet %s ", subrec->subnet_name );
    dbgtext( "for workgroup %s\n", work->work_group );
    }
</programlisting></para>

<para>(The dbgtext() function is explained below.)</para>

<para>There are a few advantages to this scheme:</para>
<orderedlist>
<listitem><para>
The test is performed only once.
</para></listitem>
<listitem><para>
You can allocate variables off of the stack that will only be used
within the DEBUGLVL() block.
</para></listitem>
<listitem><para>
Processing that is only relevant to debug output can be contained
within the DEBUGLVL() block.
</para></listitem>
</orderedlist>

</sect1>

<sect1>
<title>New Functions</title>

<sect2>
<title>dbgtext()</title>
<para>
This function prints debug message text to the debug file (and
possibly to syslog) via the format buffer. The function uses a
variable argument list just like printf() or Debug1(). The
input is printed into a buffer using the vslprintf() function,
and then passed to format_debug_text().

If you use DEBUGLVL() you will probably print the body of the
message using dbgtext(). 
</para>
</sect2>

<sect2>
<title>dbghdr()</title>
<para>
This is the function that writes a debug message header.
Headers are not processed via the format buffer. Also note that
if the format buffer is not empty, a call to dbghdr() will not
produce any output. See the comments in dbghdr() for more info.
</para>

<para>
It is not likely that this function will be called directly. It
is used by DEBUG() and DEBUGADD().
</para>
</sect2>

<sect2>
<title>format_debug_text()</title>
<para>
This is a static function in debug.c. It stores the output text
for the body of the message in a buffer until it encounters a
newline. When the newline character is found, the buffer is
written to the debug file via the Debug1() function, and the
buffer is reset. This allows us to add the indentation at the
beginning of each line of the message body, and also ensures
that the output is written a line at a time (which cleans up
syslog output).
</para>
</sect2>
</sect1>
</chapter>