A while back, Andrew and I talked about making the debug parsing code a
[samba.git] / source / lib / debug.c
1 /*
2    Unix SMB/Netbios implementation.
3    Version 1.9.
4    Samba utility functions
5    Copyright (C) Andrew Tridgell 1992-1998
6
7    This program is free software; you can redistribute it and/or modify
8    it under the terms of the GNU General Public License as published by
9    the Free Software Foundation; either version 2 of the License, or
10    (at your option) any later version.
11
12    This program is distributed in the hope that it will be useful,
13    but WITHOUT ANY WARRANTY; without even the implied warranty of
14    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
15    GNU General Public License for more details.
16
17    You should have received a copy of the GNU General Public License
18    along with this program; if not, write to the Free Software
19    Foundation, Inc., 675 Mass Ave, Cambridge, MA 02139, USA.
20 */
21
22 #include "includes.h"
23
24 /* -------------------------------------------------------------------------- **
25  * Defines...
26  *
27  *  FORMAT_BUFR_MAX - Index of the last byte of the format buffer;
28  *                    format_bufr[FORMAT_BUFR_MAX] should always be reserved
29  *                    for a terminating nul byte.
30  */
31
32 #define FORMAT_BUFR_MAX ( sizeof( format_bufr ) - 1 )
33
34 /* -------------------------------------------------------------------------- **
35  * This module implements Samba's debugging utility.
36  *
37  * The syntax of a debugging log file is represented as:
38  *
39  *  <debugfile> :== { <debugmsg> }
40  *
41  *  <debugmsg>  :== <debughdr> '\n' <debugtext>
42  *
43  *  <debughdr>  :== '[' TIME ',' LEVEL ']' [ [FILENAME ':'] [FUNCTION '()'] ]
44  *
45  *  <debugtext> :== { <debugline> }
46  *
47  *  <debugline> :== TEXT '\n'
48  *
49  * TEXT     is a string of characters excluding the newline character.
50  * LEVEL    is the DEBUG level of the message (an integer in the range 0..10).
51  * TIME     is a timestamp.
52  * FILENAME is the name of the file from which the debug message was generated.
53  * FUNCTION is the function from which the debug message was generated.
54  *
55  * Basically, what that all means is:
56  *
57  * - A debugging log file is made up of debug messages.
58  *
59  * - Each debug message is made up of a header and text.  The header is
60  *   separated from the text by a newline.
61  *
62  * - The header begins with the timestamp and debug level of the message
63  *   enclosed in brackets.  The filename and function from which the
64  *   message was generated may follow.  The filename is terminated by a
65  *   colon, and the function name is terminated by parenthesis.
66  *
67  * - The message text is made up of zero or more lines, each terminated by
68  *   a newline.
69  */
70
71 /* -------------------------------------------------------------------------- **
72  * External variables.
73  *
74  *  dbf           - Global debug file handle.
75  *  debugf        - Debug file name.
76  *  append_log    - If True, then the output file will be opened in append
77  *                  mode.
78  *  timestamp_log - 
79  *  DEBUGLEVEL    - System-wide debug message limit.  Messages with message-
80  *                  levels higher than DEBUGLEVEL will not be processed.
81  */
82
83 FILE   *dbf        = NULL;
84 pstring debugf     = "";
85 BOOL    append_log = False;
86 BOOL    timestamp_log = True;
87 int     DEBUGLEVEL = 1;
88
89
90 /* -------------------------------------------------------------------------- **
91  * Internal variables.
92  *
93  *  stdout_logging  - Default False, if set to True then dbf will be set to
94  *                    stdout and debug output will go to dbf only, and not
95  *                    to syslog.  Set in setup_logging() and read in Debug1().
96  *
97  *  debug_count     - Number of debug messages that have been output.
98  *                    Used to check log size.
99  *
100  *  syslog_level    - Internal copy of the message debug level.  Written by
101  *                    dbghdr() and read by Debug1().
102  *
103  *  format_bufr     - Used to format debug messages.  The dbgtext() function
104  *                    prints debug messages to a string, and then passes the
105  *                    string to format_debug_text(), which uses format_bufr
106  *                    to build the formatted output.
107  *
108  *  format_pos      - Marks the first free byte of the format_bufr.
109  */
110
111 static BOOL    stdout_logging = False;
112 static int     debug_count    = 0;
113 #ifdef WITH_SYSLOG
114 static int     syslog_level   = 0;
115 #endif
116 static pstring format_bufr    = { '\0' };
117 static int     format_pos     = 0;
118
119
120 /* -------------------------------------------------------------------------- **
121  * Functions...
122  */
123
124 /* ************************************************************************** **
125  * tells us if interactive logging was requested
126  * ************************************************************************** **
127  */
128 BOOL dbg_interactive(void)
129 {
130         return stdout_logging;
131 }
132
133 #if defined(SIGUSR2) && !defined(MEM_MAN)
134 /* ************************************************************************** **
135  * catch a sigusr2 - decrease the debug log level.
136  * ************************************************************************** **
137  */
138 void sig_usr2( int sig )
139   {
140   BlockSignals( True, SIGUSR2 );
141
142   DEBUGLEVEL--;
143   if( DEBUGLEVEL < 0 )
144     DEBUGLEVEL = 0;
145
146   DEBUG( 0, ( "Got SIGUSR2; set debug level to %d.\n", DEBUGLEVEL ) );
147
148   BlockSignals( False, SIGUSR2 );
149   CatchSignal( SIGUSR2, SIGNAL_CAST sig_usr2 );
150
151   } /* sig_usr2 */
152 #endif /* SIGUSR2 */
153
154 #if defined(SIGUSR1) && !defined(MEM_MAN)
155 /* ************************************************************************** **
156  * catch a sigusr1 - increase the debug log level. 
157  * ************************************************************************** **
158  */
159 void sig_usr1( int sig )
160   {
161   BlockSignals( True, SIGUSR1 );
162
163   DEBUGLEVEL++;
164
165   if( DEBUGLEVEL > 10 )
166     DEBUGLEVEL = 10;
167
168   DEBUG( 0, ( "Got SIGUSR1; set debug level to %d.\n", DEBUGLEVEL ) );
169
170   BlockSignals( False, SIGUSR1 );
171   CatchSignal( SIGUSR1, SIGNAL_CAST sig_usr1 );
172
173   } /* sig_usr1 */
174 #endif /* SIGUSR1 */
175
176
177 /* ************************************************************************** **
178  * get ready for syslog stuff
179  * ************************************************************************** **
180  */
181 void setup_logging( char *pname, BOOL interactive )
182   {
183   if( interactive )
184     {
185     stdout_logging = True;
186     dbf = stdout;
187     }
188 #ifdef WITH_SYSLOG
189   else
190     {
191     char *p = strrchr( pname,'/' );
192
193     if( p )
194       pname = p + 1;
195 #ifdef LOG_DAEMON
196     openlog( pname, LOG_PID, SYSLOG_FACILITY );
197 #else /* for old systems that have no facility codes. */
198     openlog( pname, LOG_PID );
199 #endif
200     }
201 #endif
202   } /* setup_logging */
203
204 /* ************************************************************************** **
205  * reopen the log files
206  * ************************************************************************** **
207  */
208 void reopen_logs( void )
209   {
210   pstring fname;
211   
212   if( DEBUGLEVEL > 0 )
213     {
214     pstrcpy( fname, debugf );
215     if( lp_loaded() && (*lp_logfile()) )
216       pstrcpy( fname, lp_logfile() );
217
218     if( !strcsequal( fname, debugf ) || !dbf || !file_exist( debugf, NULL ) )
219       {
220       mode_t oldumask = umask( 022 );
221
222       pstrcpy( debugf, fname );
223       if( dbf )
224         (void)fclose( dbf );
225       if( append_log )
226         dbf = sys_fopen( debugf, "a" );
227       else
228         dbf = sys_fopen( debugf, "w" );
229       /* Fix from klausr@ITAP.Physik.Uni-Stuttgart.De
230        * to fix problem where smbd's that generate less
231        * than 100 messages keep growing the log.
232        */
233       force_check_log_size();
234       if( dbf )
235         setbuf( dbf, NULL );
236       (void)umask( oldumask );
237       }
238     }
239   else
240     {
241     if( dbf )
242       {
243       (void)fclose( dbf );
244       dbf = NULL;
245       }
246     }
247   } /* reopen_logs */
248
249 /* ************************************************************************** **
250  * Force a check of the log size.
251  * ************************************************************************** **
252  */
253 void force_check_log_size( void )
254   {
255   debug_count = 100;
256   } /* force_check_log_size */
257
258 /* ************************************************************************** **
259  * Check to see if the log has grown to be too big.
260  * ************************************************************************** **
261  */
262 static void check_log_size( void )
263   {
264   int         maxlog;
265   SMB_STRUCT_STAT st;
266
267   if( debug_count++ < 100 || getuid() != 0 )
268     return;
269
270   maxlog = lp_max_log_size() * 1024;
271   if( !dbf || maxlog <= 0 )
272     return;
273
274   if( sys_fstat( fileno( dbf ), &st ) == 0 && st.st_size > maxlog )
275     {
276     (void)fclose( dbf );
277     dbf = NULL;
278     reopen_logs();
279     if( dbf && file_size( debugf ) > maxlog )
280       {
281       pstring name;
282
283       (void)fclose( dbf );
284       dbf = NULL;
285       slprintf( name, sizeof(name)-1, "%s.old", debugf );
286       (void)rename( debugf, name );
287       reopen_logs();
288       }
289     }
290   debug_count = 0;
291   } /* check_log_size */
292
293 /* ************************************************************************** **
294  * Write an debug message on the debugfile.
295  * This is called by dbghdr() and format_debug_text().
296  * ************************************************************************** **
297  */
298 #ifdef HAVE_STDARG_H
299  int Debug1( char *format_str, ... )
300 {
301 #else
302  int Debug1(va_alist)
303 va_dcl
304 {  
305   char *format_str;
306 #endif
307   va_list ap;  
308   int old_errno = errno;
309
310   if( stdout_logging )
311     {
312 #ifdef HAVE_STDARG_H
313     va_start( ap, format_str );
314 #else
315     va_start( ap );
316     format_str = va_arg( ap, char * );
317 #endif
318     (void)vfprintf( dbf, format_str, ap );
319     va_end( ap );
320     errno = old_errno;
321     return( 0 );
322     }
323   
324 #ifdef WITH_SYSLOG
325   if( !lp_syslog_only() )
326 #endif
327     {
328     if( !dbf )
329       {
330       mode_t oldumask = umask( 022 );
331
332       if( append_log )
333         dbf = sys_fopen( debugf, "a" );
334       else
335         dbf = sys_fopen( debugf, "w" );
336       (void)umask( oldumask );
337       if( dbf )
338         {
339         setbuf( dbf, NULL );
340         }
341       else
342         {
343         errno = old_errno;
344         return(0);
345         }
346       }
347     }
348
349 #ifdef WITH_SYSLOG
350   if( syslog_level < lp_syslog() )
351     {
352     /* map debug levels to syslog() priorities
353      * note that not all DEBUG(0, ...) calls are
354      * necessarily errors
355      */
356     static int priority_map[] = { 
357       LOG_ERR,     /* 0 */
358       LOG_WARNING, /* 1 */
359       LOG_NOTICE,  /* 2 */
360       LOG_INFO,    /* 3 */
361       };
362     int     priority;
363     pstring msgbuf;
364
365     if( syslog_level >= ( sizeof(priority_map) / sizeof(priority_map[0]) )
366      || syslog_level < 0)
367       priority = LOG_DEBUG;
368     else
369       priority = priority_map[syslog_level];
370       
371 #ifdef HAVE_STDARG_H
372     va_start( ap, format_str );
373 #else
374     va_start( ap );
375     format_str = va_arg( ap, char * );
376 #endif
377     vslprintf( msgbuf, sizeof(msgbuf)-1, format_str, ap );
378     va_end( ap );
379       
380     msgbuf[255] = '\0';
381     syslog( priority, "%s", msgbuf );
382     }
383 #endif
384   
385 #ifdef WITH_SYSLOG
386   if( !lp_syslog_only() )
387 #endif
388     {
389 #ifdef HAVE_STDARG_H
390     va_start( ap, format_str );
391 #else
392     va_start( ap );
393     format_str = va_arg( ap, char * );
394 #endif
395     (void)vfprintf( dbf, format_str, ap );
396     va_end( ap );
397     (void)fflush( dbf );
398     }
399
400   check_log_size();
401
402   errno = old_errno;
403
404   return( 0 );
405   } /* Debug1 */
406
407
408 /* ************************************************************************** **
409  * Print the buffer content via Debug1(), then reset the buffer.
410  *
411  *  Input:  none
412  *  Output: none
413  *
414  * ************************************************************************** **
415  */
416 static void bufr_print( void )
417   {
418   format_bufr[format_pos] = '\0';
419   (void)Debug1( "%s", format_bufr );
420   format_pos = 0;
421   } /* bufr_print */
422
423 /* ************************************************************************** **
424  * Format the debug message text.
425  *
426  *  Input:  msg - Text to be added to the "current" debug message text.
427  *
428  *  Output: none.
429  *
430  *  Notes:  The purpose of this is two-fold.  First, each call to syslog()
431  *          (used by Debug1(), see above) generates a new line of syslog
432  *          output.  This is fixed by storing the partial lines until the
433  *          newline character is encountered.  Second, printing the debug
434  *          message lines when a newline is encountered allows us to add
435  *          spaces, thus indenting the body of the message and making it
436  *          more readable.
437  *
438  * ************************************************************************** **
439  */
440 static void format_debug_text( char *msg )
441   {
442   int i;
443   BOOL timestamp = (timestamp_log && !stdout_logging && (lp_timestamp_logs() || 
444                                         !(lp_loaded())));
445
446   for( i = 0; msg[i]; i++ )
447     {
448     /* Indent two spaces at each new line. */
449     if(timestamp && 0 == format_pos)
450       {
451       format_bufr[0] = format_bufr[1] = ' ';
452       format_pos = 2;
453       }
454
455     /* If there's room, copy the character to the format buffer. */
456     if( format_pos < FORMAT_BUFR_MAX )
457       format_bufr[format_pos++] = msg[i];
458
459     /* If a newline is encountered, print & restart. */
460     if( '\n' == msg[i] )
461       bufr_print();
462
463     /* If the buffer is full dump it out, reset it, and put out a line
464      * continuation indicator.
465      */
466     if( format_pos >= FORMAT_BUFR_MAX )
467       {
468       bufr_print();
469       (void)Debug1( " +>\n" );
470       }
471     }
472
473   /* Just to be safe... */
474   format_bufr[format_pos] = '\0';
475   } /* format_debug_text */
476
477 /* ************************************************************************** **
478  * Flush debug output, including the format buffer content.
479  *
480  *  Input:  none
481  *  Output: none
482  *
483  * ************************************************************************** **
484  */
485 void dbgflush( void )
486   {
487   bufr_print();
488   (void)fflush( dbf );
489   } /* dbgflush */
490
491 /* ************************************************************************** **
492  * Print a Debug Header.
493  *
494  *  Input:  level - Debug level of the message (not the system-wide debug
495  *                  level.
496  *          file  - Pointer to a string containing the name of the file
497  *                  from which this function was called, or an empty string
498  *                  if the __FILE__ macro is not implemented.
499  *          func  - Pointer to a string containing the name of the function
500  *                  from which this function was called, or an empty string
501  *                  if the __FUNCTION__ macro is not implemented.
502  *          line  - line number of the call to dbghdr, assuming __LINE__
503  *                  works.
504  *
505  *  Output: Always True.  This makes it easy to fudge a call to dbghdr()
506  *          in a macro, since the function can be called as part of a test.
507  *          Eg: ( (level <= DEBUGLEVEL) && (dbghdr(level,"",line)) )
508  *
509  *  Notes:  This function takes care of setting syslog_level.
510  *
511  * ************************************************************************** **
512  */
513 BOOL dbghdr( int level, char *file, char *func, int line )
514   {
515   if( format_pos )
516     {
517     /* This is a fudge.  If there is stuff sitting in the format_bufr, then
518      * the *right* thing to do is to call
519      *   format_debug_text( "\n" );
520      * to write the remainder, and then proceed with the new header.
521      * Unfortunately, there are several places in the code at which
522      * the DEBUG() macro is used to build partial lines.  That in mind,
523      * we'll work under the assumption that an incomplete line indicates
524      * that a new header is *not* desired.
525      */
526     return( True );
527     }
528
529 #ifdef WITH_SYSLOG
530   /* Set syslog_level. */
531   syslog_level = level;
532 #endif
533
534   /* Don't print a header if we're logging to stdout. */
535   if( stdout_logging )
536     return( True );
537
538   /* Print the header if timestamps are turned on.  If parameters are
539    * not yet loaded, then default to timestamps on.
540    */
541   if( timestamp_log && (lp_timestamp_logs() || !(lp_loaded()) ))
542     {
543     /* Print it all out at once to prevent split syslog output. */
544     (void)Debug1( "[%s, %d] %s:%s(%d)\n",
545                   timestring(), level, file, func, line );
546     }
547
548   return( True );
549   } /* dbghdr */
550
551 /* ************************************************************************** **
552  * Add text to the body of the "current" debug message via the format buffer.
553  *
554  *  Input:  format_str  - Format string, as used in printf(), et. al.
555  *          ...         - Variable argument list.
556  *
557  *  ..or..  va_alist    - Old style variable parameter list starting point.
558  *
559  *  Output: Always True.  See dbghdr() for more info, though this is not
560  *          likely to be used in the same way.
561  *
562  * ************************************************************************** **
563  */
564 #ifdef HAVE_STDARG_H
565  BOOL dbgtext( char *format_str, ... )
566   {
567   va_list ap;
568   pstring msgbuf;
569
570   va_start( ap, format_str ); 
571   vslprintf( msgbuf, sizeof(msgbuf)-1, format_str, ap );
572   va_end( ap );
573
574   format_debug_text( msgbuf );
575
576   return( True );
577   } /* dbgtext */
578
579 #else
580  BOOL dbgtext( va_alist )
581  va_dcl
582   {
583   char *format_str;
584   va_list ap;
585   pstring msgbuf;
586
587   va_start( ap );
588   format_str = va_arg( ap, char * );
589   vslprintf( msgbuf, sizeof(msgbuf)-1, format_str, ap );
590   va_end( ap );
591
592   format_debug_text( msgbuf );
593
594   return( True );
595   } /* dbgtext */
596
597 #endif
598
599 dbg_Token dbg_char2token( dbg_Token *state, int c )
600   /* ************************************************************************ **
601    * Parse input one character at a time.
602    *
603    *  Input:  state - A pointer to a token variable.  This is used to
604    *                  maintain the parser state between calls.  For
605    *                  each input stream, you should set up a separate
606    *                  state variable and initialize it to dbg_null.
607    *                  Pass a pointer to it into this function with each
608    *                  character in the input stream.  See dbg_test()
609    *                  for an example.
610    *          c     - The "current" character in the input stream.
611    *
612    *  Output: A token.
613    *          The token value will change when delimiters are found,
614    *          which indicate a transition between syntactical objects.
615    *          Possible return values are:
616    *
617    *          dbg_null        - The input character was an end-of-line.
618    *                            This resets the parser to its initial state
619    *                            in preparation for parsing the next line.
620    *          dbg_eof         - Same as dbg_null, except that the character
621    *                            was an end-of-file.
622    *          dbg_ignore      - Returned for whitespace and delimiters.
623    *                            These lexical tokens are only of interest
624    *                            to the parser.
625    *          dbg_header      - Indicates the start of a header line.  The
626    *                            input character was '[' and was the first on
627    *                            the line.
628    *          dbg_timestamp   - Indicates that the input character was part
629    *                            of a header timestamp.
630    *          dbg_level       - Indicates that the input character was part
631    *                            of the debug-level value in the header.
632    *          dbg_sourcefile  - Indicates that the input character was part
633    *                            of the sourcefile name in the header.
634    *          dbg_function    - Indicates that the input character was part
635    *                            of the function name in the header.
636    *          dbg_lineno      - Indicates that the input character was part
637    *                            of the DEBUG call line number in the header.
638    *          dbg_message     - Indicates that the input character was part
639    *                            of the DEBUG message text.
640    *
641    * ************************************************************************ **
642    */
643   {
644   /* The terminating characters that we see will greatly depend upon
645    * how they are read.  For example, if gets() is used instead of
646    * fgets(), then we will not see newline characters.  A lot also
647    * depends on the calling function, which may handle terminators
648    * itself.
649    *
650    * '\n', '\0', and EOF are all considered line terminators.  The
651    * dbg_eof token is sent back if an EOF is encountered.
652    *
653    * Warning:  only allow the '\0' character to be sent if you are
654    *           using gets() to read whole lines (thus replacing '\n'
655    *           with '\0').  Sending '\0' at the wrong time will mess
656    *           up the parsing.
657    */
658   switch( c )
659     {
660     case EOF:
661       *state = dbg_null;   /* Set state to null (initial state) so */
662       return( dbg_eof );   /* that we can restart with new input.  */
663     case '\n':
664     case '\0':
665       *state = dbg_null;   /* A newline or eoln resets to the null state. */
666       return( dbg_null );
667     }
668
669   /* When within the body of the message, only a line terminator
670    * can cause a change of state.  We've already checked for line
671    * terminators, so if the current state is dbg_msgtxt, simply
672    * return that as our current token.
673    */
674   if( dbg_message == *state )
675     return( dbg_message );
676
677   /* If we are at the start of a new line, and the input character 
678    * is an opening bracket, then the line is a header line, otherwise
679    * it's a message body line.
680    */
681   if( dbg_null == *state )
682     {
683     if( '[' == c )
684       {
685       *state = dbg_timestamp;
686       return( dbg_header );
687       }
688     *state = dbg_message;
689     return( dbg_message );
690     }
691
692   /* We've taken care of terminators, text blocks and new lines.
693    * The remaining possibilities are all within the header line
694    * itself.
695    */
696
697   /* Within the header line, whitespace can be ignored *except*
698    * within the timestamp.
699    */
700   if( isspace( c ) )
701     {
702     /* Fudge.  The timestamp may contain space characters. */
703     if( (' ' == c) && (dbg_timestamp == *state) )
704       return( dbg_timestamp );
705     /* Otherwise, ignore whitespace. */
706     return( dbg_ignore );
707     }
708
709   /* Okay, at this point we know we're somewhere in the header.
710    * Valid header *states* are: dbg_timestamp, dbg_level,
711    * dbg_sourcefile, dbg_function, and dbg_lineno.
712    */
713   switch( c )
714     {
715     case ',':
716       if( dbg_timestamp == *state )
717         {
718         *state = dbg_level;
719         return( dbg_ignore );
720         }
721       break;
722     case ']':
723       if( dbg_level == *state )
724         {
725         *state = dbg_sourcefile;
726         return( dbg_ignore );
727         }
728       break;
729     case ':':
730       if( dbg_sourcefile == *state )
731         {
732         *state = dbg_function;
733         return( dbg_ignore );
734         }
735       break;
736     case '(':
737       if( dbg_function == *state )
738         {
739         *state = dbg_lineno;
740         return( dbg_ignore );
741         }
742       break;
743     case ')':
744       if( dbg_lineno == *state )
745         {
746         *state = dbg_null;
747         return( dbg_ignore );
748         }
749       break;
750     }
751
752   /* If the previous block did not result in a state change, then
753    * return the current state as the current token.
754    */
755   return( *state );
756   } /* dbg_char2token */
757
758 /* ************************************************************************** */