Hey what happened to my debug messages? Early exit from reopen_logs()
[nivanova/samba-autobuild/.git] / source3 / 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  *  DEBUGLEVEL    - System-wide debug message limit.  Messages with message-
79  *                  levels higher than DEBUGLEVEL will not be processed.
80  */
81
82 FILE   *dbf        = NULL;
83 pstring debugf     = "";
84 BOOL    append_log = False;
85
86 int     DEBUGLEVEL_CLASS[DBGC_LAST];
87 int     DEBUGLEVEL = DEBUGLEVEL_CLASS;
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  *  log_overflow    - When this variable is True, never attempt to check the
112  *                    size of the log. This is a hack, so that we can write
113  *                    a message using DEBUG, from open_logs() when we
114  *                    are unable to open a new log file for some reason.
115  */
116
117 static BOOL    stdout_logging = False;
118 static int     debug_count    = 0;
119 #ifdef WITH_SYSLOG
120 static int     syslog_level   = 0;
121 #endif
122 static pstring format_bufr    = { '\0' };
123 static size_t     format_pos     = 0;
124 static BOOL    log_overflow   = False;
125
126 /*
127 * Define all the debug class selection names here. Names *MUST NOT* contain 
128 * white space. There must be one name for each DBGC_<class name>, and they 
129 * must be in the table in the order of DBGC_<class name>.. 
130 */
131 char *classname_table[] = {
132         "all",               /* DBGC_ALL; index references traditional DEBUGLEVEL */
133         "tdb",               /* DBGC_TDB        */
134         "printdrivers",      /* DBGC_PRINTDRIVERS */
135         "lanman",            /* DBGC_LANMAN */
136         "smb",               /* DBGC_SMB */
137         "rpc",               /* DBGC_RPC */
138         "rpc_hdr",           /* DBGC_RPC_HDR */
139 };
140
141
142 /* -------------------------------------------------------------------------- **
143  * Functions...
144  */
145
146 /****************************************************************************
147 utility access to debug class names's
148 ****************************************************************************/
149 char* debug_classname_from_index(int ndx)
150 {
151         return classname_table[ndx];
152 }
153
154 /****************************************************************************
155 utility to translate names to debug class index's
156 ****************************************************************************/
157 int debug_lookup_classname(char* classname)
158 {
159         int i;
160
161         if (!classname) return -1;
162
163         for (i=0; i<DBGC_LAST; i++) {
164                 if (strcmp(classname, classname_table[i])==0)
165                         return i;
166         }
167         return -1;
168 }
169
170 /****************************************************************************
171 parse the debug levels from smbcontrol. Example debug level parameter:
172   printdrivers:7
173 ****************************************************************************/
174 BOOL debug_parse_params(char **params, int *debuglevel_class)
175 {
176         int   i, ndx;
177         char *class_name;
178         char *class_level;
179         
180         /* Set the new debug level array to the current DEBUGLEVEL array */
181         memcpy(debuglevel_class, DEBUGLEVEL_CLASS, sizeof(DEBUGLEVEL_CLASS));
182
183         /* Allow DBGC_ALL to be specifies w/o requiring its class name e.g."10"  
184          * v.s. "all:10", this is the traditional way to set DEBUGLEVEL 
185          */
186         if (isdigit((int)params[0][0])) {
187                 debuglevel_class[DBGC_ALL] = atoi(params[0]);
188                 i = 1; /* start processing at the next params */
189         }
190         else
191                 i = 0; /* DBGC_ALL not specified  OR calss name was included */
192
193         /* Fill in new debug class levels */
194         for (; i < DBGC_LAST && params[i]; i++) {
195                 if ((class_name=strtok(params[i],":")) &&
196                         (class_level=strtok(NULL, "\0")) &&
197             ((ndx = debug_lookup_classname(class_name)) != -1)) {
198                                 debuglevel_class[ndx] = atoi(class_level);
199                 } else {
200                         DEBUG(0,("debug_parse_params: unrecognized debug class name or format [%s]\n", params[i]));
201                         return False;
202                 }
203         }
204
205         return True;
206 }
207
208 /****************************************************************************
209 parse the debug levels from smb.conf. Example debug level string:
210   3 tdb:5 printdrivers:7
211 Note: the 1st param has no "name:" preceeding it.
212 ****************************************************************************/
213 BOOL debug_parse_levels(char *params_str)
214 {
215         int  i;
216         char *params[DBGC_LAST];
217         int  debuglevel_class[DBGC_LAST];       
218
219         ZERO_ARRAY(params);
220         ZERO_ARRAY(debuglevel_class);
221
222         if ((params[0]=strtok(params_str," ,"))) {
223                 for (i=1; i<DBGC_LAST;i++) {
224                         if ((params[i]=strtok(NULL," ,"))==NULL)
225                                 break;
226                 }
227         }
228         else
229                 return False;
230
231         if (debug_parse_params(params, debuglevel_class)) {
232                 debug_message(0, getpid(), (void*)debuglevel_class, sizeof(debuglevel_class));
233
234 #if 0
235                 memcpy(DEBUGLEVEL_CLASS, debuglevel_class, 
236                        sizeof(debuglevel_class));
237 #endif
238                 return True;
239         } else
240                 return False;
241 }
242
243 /****************************************************************************
244 receive a "set debug level" message
245 ****************************************************************************/
246 void debug_message(int msg_type, pid_t src, void *buf, size_t len)
247 {
248         int i;
249
250         /* Set the new DEBUGLEVEL_CLASS array from the pased array */
251         memcpy(DEBUGLEVEL_CLASS, buf, sizeof(DEBUGLEVEL_CLASS));
252         
253         DEBUG(1,("INFO: Debug class %s level = %d   (pid %u from pid %u)\n",
254                         classname_table[DBGC_ALL],
255                         DEBUGLEVEL_CLASS[DBGC_ALL], (unsigned int)getpid(), (unsigned int)src));
256
257         for (i=1; i<DBGC_LAST; i++) {
258                 if (DEBUGLEVEL_CLASS[i])
259                          DEBUGADD(1,("INFO: Debug class %s level = %d\n", 
260                                                 classname_table[i], DEBUGLEVEL_CLASS[i]));
261         }
262 }
263
264
265 /****************************************************************************
266 send a "set debug level" message
267 ****************************************************************************/
268 void debug_message_send(pid_t pid, int level)
269 {
270         message_send_pid(pid, MSG_DEBUG, &level, sizeof(int), False);
271 }
272
273
274 /* ************************************************************************** **
275  * get ready for syslog stuff
276  * ************************************************************************** **
277  */
278 void setup_logging(char *pname, BOOL interactive)
279 {
280         message_register(MSG_DEBUG, debug_message);
281
282         /* reset to allow multiple setup calls, going from interactive to
283            non-interactive */
284         stdout_logging = False;
285         dbf = NULL;
286
287         if (interactive) {
288                 stdout_logging = True;
289                 dbf = stdout;
290         }
291 #ifdef WITH_SYSLOG
292         else {
293                 char *p = strrchr( pname,'/' );
294                 if (p)
295                         pname = p + 1;
296 #ifdef LOG_DAEMON
297                 openlog( pname, LOG_PID, SYSLOG_FACILITY );
298 #else /* for old systems that have no facility codes. */
299                 openlog( pname, LOG_PID );
300 #endif
301         }
302 #endif
303 } /* setup_logging */
304
305 /* ************************************************************************** **
306  * reopen the log files
307  * note that we now do this unconditionally
308  * We attempt to open the new debug fp before closing the old. This means
309  * if we run out of fd's we just keep using the old fd rather than aborting.
310  * Fix from dgibson@linuxcare.com.
311  * ************************************************************************** **
312  */
313
314 BOOL reopen_logs( void )
315 {
316         pstring fname;
317         mode_t oldumask;
318         FILE *new_dbf = NULL;
319         BOOL ret = True;
320
321         if (stdout_logging)
322                 return True;
323
324         if (DEBUGLEVEL_CLASS[ DBGC_ALL ] <= 0) {
325                 if (dbf) {
326                         (void)fclose(dbf);
327                         dbf = NULL;
328                 }
329                 return True;
330         }
331
332         oldumask = umask( 022 );
333   
334         pstrcpy(fname, debugf );
335         if (lp_loaded() && (*lp_logfile()))
336                 pstrcpy(fname, lp_logfile());
337
338         pstrcpy( debugf, fname );
339         if (append_log)
340                 new_dbf = sys_fopen( debugf, "a" );
341         else
342                 new_dbf = sys_fopen( debugf, "w" );
343
344         if (!new_dbf) {
345                 log_overflow = True;
346                 DEBUG(0, ("Unable to open new log file %s: %s\n", debugf, strerror(errno)));
347                 log_overflow = False;
348                 fflush(dbf);
349                 ret = False;
350         } else {
351                 setbuf(new_dbf, NULL);
352                 if (dbf)
353                         (void) fclose(dbf);
354                 dbf = new_dbf;
355         }
356
357         /* Fix from klausr@ITAP.Physik.Uni-Stuttgart.De
358          * to fix problem where smbd's that generate less
359          * than 100 messages keep growing the log.
360          */
361         force_check_log_size();
362         (void)umask(oldumask);
363
364         return ret;
365 }
366
367 /* ************************************************************************** **
368  * Force a check of the log size.
369  * ************************************************************************** **
370  */
371 void force_check_log_size( void )
372 {
373   debug_count = 100;
374 }
375
376 /***************************************************************************
377  Check to see if there is any need to check if the logfile has grown too big.
378 **************************************************************************/
379
380 BOOL need_to_check_log_size( void )
381 {
382         int maxlog;
383
384         if( debug_count++ < 100 )
385                 return( False );
386
387         maxlog = lp_max_log_size() * 1024;
388         if( !dbf || maxlog <= 0 ) {
389                 debug_count = 0;
390                 return(False);
391         }
392         return( True );
393 }
394
395 /* ************************************************************************** **
396  * Check to see if the log has grown to be too big.
397  * ************************************************************************** **
398  */
399
400 void check_log_size( void )
401 {
402         int         maxlog;
403         SMB_STRUCT_STAT st;
404
405         /*
406          *  We need to be root to check/change log-file, skip this and let the main
407          *  loop check do a new check as root.
408          */
409
410         if( geteuid() != 0 )
411                 return;
412
413         if(log_overflow || !need_to_check_log_size() )
414                 return;
415
416         maxlog = lp_max_log_size() * 1024;
417
418         if( sys_fstat( fileno( dbf ), &st ) == 0 && st.st_size > maxlog ) {
419                 (void)reopen_logs();
420                 if( dbf && get_file_size( debugf ) > maxlog ) {
421                         pstring name;
422
423                         slprintf( name, sizeof(name)-1, "%s.old", debugf );
424                         (void)rename( debugf, name );
425       
426                         if (!reopen_logs()) {
427                                 /* We failed to reopen a log - continue using the old name. */
428                                 (void)rename(name, debugf);
429                         }
430                 }
431         }
432
433         /*
434          * Here's where we need to panic if dbf == NULL..
435          */
436
437         if(dbf == NULL) {
438                 /* This code should only be reached in very strange
439                         circumstances. If we merely fail to open the new log we
440                         should stick with the old one. ergo this should only be
441                         reached when opening the logs for the first time: at
442                         startup or when the log level is increased from zero.
443                         -dwg 6 June 2000
444                 */
445                 dbf = sys_fopen( "/dev/console", "w" );
446                 if(dbf) {
447                         DEBUG(0,("check_log_size: open of debug file %s failed - using console.\n",
448                                         debugf ));
449                 } else {
450                         /*
451                          * We cannot continue without a debug file handle.
452                          */
453                         abort();
454                 }
455         }
456         debug_count = 0;
457 } /* check_log_size */
458
459 /* ************************************************************************** **
460  * Write an debug message on the debugfile.
461  * This is called by dbghdr() and format_debug_text().
462  * ************************************************************************** **
463  */
464  int Debug1( char *format_str, ... )
465 {
466   va_list ap;  
467   int old_errno = errno;
468
469   if( stdout_logging )
470     {
471     va_start( ap, format_str );
472     if(dbf)
473       (void)vfprintf( dbf, format_str, ap );
474     va_end( ap );
475     errno = old_errno;
476     return( 0 );
477     }
478   
479 #ifdef WITH_SYSLOG
480   if( !lp_syslog_only() )
481 #endif
482     {
483     if( !dbf )
484       {
485       mode_t oldumask = umask( 022 );
486
487       if( append_log )
488         dbf = sys_fopen( debugf, "a" );
489       else
490         dbf = sys_fopen( debugf, "w" );
491       (void)umask( oldumask );
492       if( dbf )
493         {
494         setbuf( dbf, NULL );
495         }
496       else
497         {
498         errno = old_errno;
499         return(0);
500         }
501       }
502     }
503
504 #ifdef WITH_SYSLOG
505   if( syslog_level < lp_syslog() )
506     {
507     /* map debug levels to syslog() priorities
508      * note that not all DEBUG(0, ...) calls are
509      * necessarily errors
510      */
511     static int priority_map[] = { 
512       LOG_ERR,     /* 0 */
513       LOG_WARNING, /* 1 */
514       LOG_NOTICE,  /* 2 */
515       LOG_INFO,    /* 3 */
516       };
517     int     priority;
518     pstring msgbuf;
519
520     if( syslog_level >= ( sizeof(priority_map) / sizeof(priority_map[0]) )
521      || syslog_level < 0)
522       priority = LOG_DEBUG;
523     else
524       priority = priority_map[syslog_level];
525       
526     va_start( ap, format_str );
527     vslprintf( msgbuf, sizeof(msgbuf)-1, format_str, ap );
528     va_end( ap );
529       
530     msgbuf[255] = '\0';
531     syslog( priority, "%s", msgbuf );
532     }
533 #endif
534   
535   check_log_size();
536
537 #ifdef WITH_SYSLOG
538   if( !lp_syslog_only() )
539 #endif
540     {
541     va_start( ap, format_str );
542     if(dbf)
543       (void)vfprintf( dbf, format_str, ap );
544     va_end( ap );
545     if(dbf)
546       (void)fflush( dbf );
547     }
548
549   errno = old_errno;
550
551   return( 0 );
552   } /* Debug1 */
553
554
555 /* ************************************************************************** **
556  * Print the buffer content via Debug1(), then reset the buffer.
557  *
558  *  Input:  none
559  *  Output: none
560  *
561  * ************************************************************************** **
562  */
563 static void bufr_print( void )
564   {
565   format_bufr[format_pos] = '\0';
566   (void)Debug1( "%s", format_bufr );
567   format_pos = 0;
568   } /* bufr_print */
569
570 /* ************************************************************************** **
571  * Format the debug message text.
572  *
573  *  Input:  msg - Text to be added to the "current" debug message text.
574  *
575  *  Output: none.
576  *
577  *  Notes:  The purpose of this is two-fold.  First, each call to syslog()
578  *          (used by Debug1(), see above) generates a new line of syslog
579  *          output.  This is fixed by storing the partial lines until the
580  *          newline character is encountered.  Second, printing the debug
581  *          message lines when a newline is encountered allows us to add
582  *          spaces, thus indenting the body of the message and making it
583  *          more readable.
584  *
585  * ************************************************************************** **
586  */
587 static void format_debug_text( char *msg )
588   {
589   size_t i;
590   BOOL timestamp = (!stdout_logging && (lp_timestamp_logs() || 
591                                         !(lp_loaded())));
592
593   for( i = 0; msg[i]; i++ )
594     {
595     /* Indent two spaces at each new line. */
596     if(timestamp && 0 == format_pos)
597       {
598       format_bufr[0] = format_bufr[1] = ' ';
599       format_pos = 2;
600       }
601
602     /* If there's room, copy the character to the format buffer. */
603     if( format_pos < FORMAT_BUFR_MAX )
604       format_bufr[format_pos++] = msg[i];
605
606     /* If a newline is encountered, print & restart. */
607     if( '\n' == msg[i] )
608       bufr_print();
609
610     /* If the buffer is full dump it out, reset it, and put out a line
611      * continuation indicator.
612      */
613     if( format_pos >= FORMAT_BUFR_MAX )
614       {
615       bufr_print();
616       (void)Debug1( " +>\n" );
617       }
618     }
619
620   /* Just to be safe... */
621   format_bufr[format_pos] = '\0';
622   } /* format_debug_text */
623
624 /* ************************************************************************** **
625  * Flush debug output, including the format buffer content.
626  *
627  *  Input:  none
628  *  Output: none
629  *
630  * ************************************************************************** **
631  */
632 void dbgflush( void )
633   {
634   bufr_print();
635   if(dbf)
636     (void)fflush( dbf );
637   } /* dbgflush */
638
639 /* ************************************************************************** **
640  * Print a Debug Header.
641  *
642  *  Input:  level - Debug level of the message (not the system-wide debug
643  *                  level.
644  *          file  - Pointer to a string containing the name of the file
645  *                  from which this function was called, or an empty string
646  *                  if the __FILE__ macro is not implemented.
647  *          func  - Pointer to a string containing the name of the function
648  *                  from which this function was called, or an empty string
649  *                  if the __FUNCTION__ macro is not implemented.
650  *          line  - line number of the call to dbghdr, assuming __LINE__
651  *                  works.
652  *
653  *  Output: Always True.  This makes it easy to fudge a call to dbghdr()
654  *          in a macro, since the function can be called as part of a test.
655  *          Eg: ( (level <= DEBUGLEVEL) && (dbghdr(level,"",line)) )
656  *
657  *  Notes:  This function takes care of setting syslog_level.
658  *
659  * ************************************************************************** **
660  */
661
662 BOOL dbghdr( int level, char *file, char *func, int line )
663 {
664   /* Ensure we don't lose any real errno value. */
665   int old_errno = errno;
666
667   if( format_pos ) {
668     /* This is a fudge.  If there is stuff sitting in the format_bufr, then
669      * the *right* thing to do is to call
670      *   format_debug_text( "\n" );
671      * to write the remainder, and then proceed with the new header.
672      * Unfortunately, there are several places in the code at which
673      * the DEBUG() macro is used to build partial lines.  That in mind,
674      * we'll work under the assumption that an incomplete line indicates
675      * that a new header is *not* desired.
676      */
677     return( True );
678   }
679
680 #ifdef WITH_SYSLOG
681   /* Set syslog_level. */
682   syslog_level = level;
683 #endif
684
685   /* Don't print a header if we're logging to stdout. */
686   if( stdout_logging )
687     return( True );
688
689   /* Print the header if timestamps are turned on.  If parameters are
690    * not yet loaded, then default to timestamps on.
691    */
692   if( lp_timestamp_logs() || !(lp_loaded()) ) {
693     char header_str[200];
694
695         header_str[0] = '\0';
696
697         if( lp_debug_pid())
698           slprintf(header_str,sizeof(header_str)-1,", pid=%u",(unsigned int)sys_getpid());
699
700         if( lp_debug_uid()) {
701       size_t hs_len = strlen(header_str);
702           slprintf(header_str + hs_len,
703                sizeof(header_str) - 1 - hs_len,
704                            ", effective(%u, %u), real(%u, %u)",
705                (unsigned int)geteuid(), (unsigned int)getegid(),
706                            (unsigned int)getuid(), (unsigned int)getgid()); 
707         }
708   
709     /* Print it all out at once to prevent split syslog output. */
710     (void)Debug1( "[%s, %d%s] %s:%s(%d)\n",
711                   timestring(lp_debug_hires_timestamp()), level,
712                                   header_str, file, func, line );
713   }
714
715   errno = old_errno;
716   return( True );
717 }
718
719 /* ************************************************************************** **
720  * Add text to the body of the "current" debug message via the format buffer.
721  *
722  *  Input:  format_str  - Format string, as used in printf(), et. al.
723  *          ...         - Variable argument list.
724  *
725  *  ..or..  va_alist    - Old style variable parameter list starting point.
726  *
727  *  Output: Always True.  See dbghdr() for more info, though this is not
728  *          likely to be used in the same way.
729  *
730  * ************************************************************************** **
731  */
732  BOOL dbgtext( char *format_str, ... )
733   {
734   va_list ap;
735   pstring msgbuf;
736
737   va_start( ap, format_str ); 
738   vslprintf( msgbuf, sizeof(msgbuf)-1, format_str, ap );
739   va_end( ap );
740
741   format_debug_text( msgbuf );
742
743   return( True );
744   } /* dbgtext */
745
746
747 /* ************************************************************************** */