Code sync
[external/cups.git] / cups / debug.c
1 /*
2  * "$Id: debug.c 10234 2012-02-06 19:35:59Z mike $"
3  *
4  *   Debugging functions for CUPS.
5  *
6  *   Copyright 2008-2012 by Apple Inc.
7  *
8  *   These coded instructions, statements, and computer programs are the
9  *   property of Apple Inc. and are protected by Federal copyright
10  *   law.  Distribution and use rights are outlined in the file "LICENSE.txt"
11  *   which should have been included with this file.  If this file is
12  *   file is missing or damaged, see the license at "http://www.cups.org/".
13  *
14  *   This file is subject to the Apple OS-Developed Software exception.
15  *
16  * Contents:
17  *
18  *   debug_vsnprintf()    - Format a string into a fixed size buffer.
19  *   _cups_debug_printf() - Write a formatted line to the log.
20  *   _cups_debug_puts()   - Write a single line to the log.
21  *   _cups_debug_set()    - Enable or disable debug logging.
22  */
23
24 /*
25  * Include necessary headers...
26  */
27
28 #include "cups-private.h"
29 #include "thread-private.h"
30 #ifdef WIN32
31 #  include <sys/timeb.h>
32 #  include <time.h>
33 #  include <io.h>
34 #  define getpid (int)GetCurrentProcessId
35 int                                     /* O  - 0 on success, -1 on failure */
36 _cups_gettimeofday(struct timeval *tv,  /* I  - Timeval struct */
37                    void           *tz)  /* I  - Timezone */
38 {
39   struct _timeb timebuffer;             /* Time buffer struct */
40   _ftime(&timebuffer);
41   tv->tv_sec  = (long)timebuffer.time;
42   tv->tv_usec = timebuffer.millitm * 1000;
43   return 0;
44 }
45 #else
46 #  include <sys/time.h>
47 #  include <unistd.h>
48 #endif /* WIN32 */
49 #include <regex.h>
50 #include <fcntl.h>
51
52
53 /*
54  * Globals...
55  */
56
57 int                     _cups_debug_fd = -1;
58                                         /* Debug log file descriptor */
59 int                     _cups_debug_level = 1;
60                                         /* Log level (0 to 9) */
61
62
63 #ifdef DEBUG
64 /*
65  * Local globals...
66  */
67
68 static regex_t          *debug_filter = NULL;
69                                         /* Filter expression for messages */
70 static int              debug_init = 0; /* Did we initialize debugging? */
71 static _cups_mutex_t    debug_mutex = _CUPS_MUTEX_INITIALIZER;
72                                         /* Mutex to control initialization */
73
74
75 /*
76  * 'debug_vsnprintf()' - Format a string into a fixed size buffer.
77  */
78
79 static int                              /* O - Number of bytes formatted */
80 debug_vsnprintf(char       *buffer,     /* O - Output buffer */
81                 size_t     bufsize,     /* O - Size of output buffer */
82                 const char *format,     /* I - printf-style format string */
83                 va_list    ap)          /* I - Pointer to additional arguments */
84 {
85   char          *bufptr,                /* Pointer to position in buffer */
86                 *bufend,                /* Pointer to end of buffer */
87                 size,                   /* Size character (h, l, L) */
88                 type;                   /* Format type character */
89   int           width,                  /* Width of field */
90                 prec;                   /* Number of characters of precision */
91   char          tformat[100],           /* Temporary format string for sprintf() */
92                 *tptr,                  /* Pointer into temporary format */
93                 temp[1024];             /* Buffer for formatted numbers */
94   char          *s;                     /* Pointer to string */
95   int           bytes;                  /* Total number of bytes needed */
96
97
98   if (!buffer || bufsize < 2 || !format)
99     return (-1);
100
101  /*
102   * Loop through the format string, formatting as needed...
103   */
104
105   bufptr = buffer;
106   bufend = buffer + bufsize - 1;
107   bytes  = 0;
108
109   while (*format)
110   {
111     if (*format == '%')
112     {
113       tptr = tformat;
114       *tptr++ = *format++;
115
116       if (*format == '%')
117       {
118         if (bufptr < bufend)
119           *bufptr++ = *format;
120         bytes ++;
121         format ++;
122         continue;
123       }
124       else if (strchr(" -+#\'", *format))
125         *tptr++ = *format++;
126
127       if (*format == '*')
128       {
129        /*
130         * Get width from argument...
131         */
132
133         format ++;
134         width = va_arg(ap, int);
135
136         snprintf(tptr, sizeof(tformat) - (tptr - tformat), "%d", width);
137         tptr += strlen(tptr);
138       }
139       else
140       {
141         width = 0;
142
143         while (isdigit(*format & 255))
144         {
145           if (tptr < (tformat + sizeof(tformat) - 1))
146             *tptr++ = *format;
147
148           width = width * 10 + *format++ - '0';
149         }
150       }
151
152       if (*format == '.')
153       {
154         if (tptr < (tformat + sizeof(tformat) - 1))
155           *tptr++ = *format;
156
157         format ++;
158
159         if (*format == '*')
160         {
161          /*
162           * Get precision from argument...
163           */
164
165           format ++;
166           prec = va_arg(ap, int);
167
168           snprintf(tptr, sizeof(tformat) - (tptr - tformat), "%d", prec);
169           tptr += strlen(tptr);
170         }
171         else
172         {
173           prec = 0;
174
175           while (isdigit(*format & 255))
176           {
177             if (tptr < (tformat + sizeof(tformat) - 1))
178               *tptr++ = *format;
179
180             prec = prec * 10 + *format++ - '0';
181           }
182         }
183       }
184
185       if (*format == 'l' && format[1] == 'l')
186       {
187         size = 'L';
188
189         if (tptr < (tformat + sizeof(tformat) - 2))
190         {
191           *tptr++ = 'l';
192           *tptr++ = 'l';
193         }
194
195         format += 2;
196       }
197       else if (*format == 'h' || *format == 'l' || *format == 'L')
198       {
199         if (tptr < (tformat + sizeof(tformat) - 1))
200           *tptr++ = *format;
201
202         size = *format++;
203       }
204       else
205         size = 0;
206
207       if (!*format)
208         break;
209
210       if (tptr < (tformat + sizeof(tformat) - 1))
211         *tptr++ = *format;
212
213       type  = *format++;
214       *tptr = '\0';
215
216       switch (type)
217       {
218         case 'E' : /* Floating point formats */
219         case 'G' :
220         case 'e' :
221         case 'f' :
222         case 'g' :
223             if ((width + 2) > sizeof(temp))
224               break;
225
226             sprintf(temp, tformat, va_arg(ap, double));
227
228             bytes += (int)strlen(temp);
229
230             if (bufptr)
231             {
232               if ((bufptr + strlen(temp)) > bufend)
233               {
234                 strncpy(bufptr, temp, (size_t)(bufend - bufptr));
235                 bufptr = bufend;
236               }
237               else
238               {
239                 strcpy(bufptr, temp);
240                 bufptr += strlen(temp);
241               }
242             }
243             break;
244
245         case 'B' : /* Integer formats */
246         case 'X' :
247         case 'b' :
248         case 'd' :
249         case 'i' :
250         case 'o' :
251         case 'u' :
252         case 'x' :
253             if ((width + 2) > sizeof(temp))
254               break;
255
256 #  ifdef HAVE_LONG_LONG
257             if (size == 'L')
258               sprintf(temp, tformat, va_arg(ap, long long));
259             else
260 #  endif /* HAVE_LONG_LONG */
261             if (size == 'l')
262               sprintf(temp, tformat, va_arg(ap, long));
263             else
264               sprintf(temp, tformat, va_arg(ap, int));
265
266             bytes += (int)strlen(temp);
267
268             if (bufptr)
269             {
270               if ((bufptr + strlen(temp)) > bufend)
271               {
272                 strncpy(bufptr, temp, (size_t)(bufend - bufptr));
273                 bufptr = bufend;
274               }
275               else
276               {
277                 strcpy(bufptr, temp);
278                 bufptr += strlen(temp);
279               }
280             }
281             break;
282
283         case 'p' : /* Pointer value */
284             if ((width + 2) > sizeof(temp))
285               break;
286
287             sprintf(temp, tformat, va_arg(ap, void *));
288
289             bytes += (int)strlen(temp);
290
291             if (bufptr)
292             {
293               if ((bufptr + strlen(temp)) > bufend)
294               {
295                 strncpy(bufptr, temp, (size_t)(bufend - bufptr));
296                 bufptr = bufend;
297               }
298               else
299               {
300                 strcpy(bufptr, temp);
301                 bufptr += strlen(temp);
302               }
303             }
304             break;
305
306         case 'c' : /* Character or character array */
307             bytes += width;
308
309             if (bufptr)
310             {
311               if (width <= 1)
312                 *bufptr++ = va_arg(ap, int);
313               else
314               {
315                 if ((bufptr + width) > bufend)
316                   width = (int)(bufend - bufptr);
317
318                 memcpy(bufptr, va_arg(ap, char *), (size_t)width);
319                 bufptr += width;
320               }
321             }
322             break;
323
324         case 's' : /* String */
325             if ((s = va_arg(ap, char *)) == NULL)
326               s = "(null)";
327
328            /*
329             * Copy the C string, replacing control chars and \ with
330             * C character escapes...
331             */
332
333             for (bufend --; *s && bufptr < bufend; s ++)
334             {
335               if (*s == '\n')
336               {
337                 *bufptr++ = '\\';
338                 *bufptr++ = 'n';
339                 bytes += 2;
340               }
341               else if (*s == '\r')
342               {
343                 *bufptr++ = '\\';
344                 *bufptr++ = 'r';
345                 bytes += 2;
346               }
347               else if (*s == '\t')
348               {
349                 *bufptr++ = '\\';
350                 *bufptr++ = 't';
351                 bytes += 2;
352               }
353               else if (*s == '\\')
354               {
355                 *bufptr++ = '\\';
356                 *bufptr++ = '\\';
357                 bytes += 2;
358               }
359               else if (*s == '\'')
360               {
361                 *bufptr++ = '\\';
362                 *bufptr++ = '\'';
363                 bytes += 2;
364               }
365               else if (*s == '\"')
366               {
367                 *bufptr++ = '\\';
368                 *bufptr++ = '\"';
369                 bytes += 2;
370               }
371               else if ((*s & 255) < ' ')
372               {
373                 if ((bufptr + 2) >= bufend)
374                   break;
375
376                 *bufptr++ = '\\';
377                 *bufptr++ = '0';
378                 *bufptr++ = '0' + *s / 8;
379                 *bufptr++ = '0' + (*s & 7);
380                 bytes += 4;
381               }
382               else
383               {
384                 *bufptr++ = *s;
385                 bytes ++;
386               }
387             }
388
389             bufend ++;
390             break;
391
392         case 'n' : /* Output number of chars so far */
393             *(va_arg(ap, int *)) = bytes;
394             break;
395       }
396     }
397     else
398     {
399       bytes ++;
400
401       if (bufptr < bufend)
402         *bufptr++ = *format;
403
404       format ++;
405     }
406   }
407
408  /*
409   * Nul-terminate the string and return the number of characters needed.
410   */
411
412   *bufptr = '\0';
413
414   return (bytes);
415 }
416
417
418 /*
419  * '_cups_debug_printf()' - Write a formatted line to the log.
420  */
421
422 void DLLExport
423 _cups_debug_printf(const char *format,  /* I - Printf-style format string */
424                    ...)                 /* I - Additional arguments as needed */
425 {
426   va_list               ap;             /* Pointer to arguments */
427   struct timeval        curtime;        /* Current time */
428   char                  buffer[2048];   /* Output buffer */
429   size_t                bytes;          /* Number of bytes in buffer */
430   int                   level;          /* Log level in message */
431
432
433  /*
434   * See if we need to do any logging...
435   */
436
437   if (!debug_init)
438     _cups_debug_set(getenv("CUPS_DEBUG_LOG"), getenv("CUPS_DEBUG_LEVEL"),
439                     getenv("CUPS_DEBUG_FILTER"), 0);
440
441   if (_cups_debug_fd < 0)
442     return;
443
444  /*
445   * Filter as needed...
446   */
447
448   if (isdigit(format[0]))
449     level = *format++ - '0';
450   else
451     level = 0;
452
453   if (level > _cups_debug_level)
454     return;
455
456   if (debug_filter)
457   {
458     int result;                         /* Filter result */
459
460     _cupsMutexLock(&debug_mutex);
461     result = regexec(debug_filter, format, 0, NULL, 0);
462     _cupsMutexUnlock(&debug_mutex);
463
464     if (result)
465       return;
466   }
467
468  /*
469   * Format the message...
470   */
471
472   gettimeofday(&curtime, NULL);
473   snprintf(buffer, sizeof(buffer), "%02d:%02d:%02d.%03d ",
474            (int)((curtime.tv_sec / 3600) % 24),
475            (int)((curtime.tv_sec / 60) % 60),
476            (int)(curtime.tv_sec % 60), (int)(curtime.tv_usec / 1000));
477
478   va_start(ap, format);
479   bytes = debug_vsnprintf(buffer + 13, sizeof(buffer) - 14, format, ap) + 13;
480   va_end(ap);
481
482   if (bytes >= (sizeof(buffer) - 1))
483   {
484     buffer[sizeof(buffer) - 2] = '\n';
485     bytes = sizeof(buffer) - 1;
486   }
487   else if (buffer[bytes - 1] != '\n')
488   {
489     buffer[bytes++] = '\n';
490     buffer[bytes]   = '\0';
491   }
492
493  /*
494   * Write it out...
495   */
496
497   write(_cups_debug_fd, buffer, bytes);
498 }
499
500
501 /*
502  * '_cups_debug_puts()' - Write a single line to the log.
503  */
504
505 void DLLExport
506 _cups_debug_puts(const char *s)         /* I - String to output */
507 {
508   struct timeval        curtime;        /* Current time */
509   char                  buffer[2048];   /* Output buffer */
510   size_t                bytes;          /* Number of bytes in buffer */
511   int                   level;          /* Log level in message */
512
513
514  /*
515   * See if we need to do any logging...
516   */
517
518   if (!debug_init)
519     _cups_debug_set(getenv("CUPS_DEBUG_LOG"), getenv("CUPS_DEBUG_LEVEL"),
520                     getenv("CUPS_DEBUG_FILTER"), 0);
521
522   if (_cups_debug_fd < 0)
523     return;
524
525  /*
526   * Filter as needed...
527   */
528
529   if (isdigit(s[0]))
530     level = *s++ - '0';
531   else
532     level = 0;
533
534   if (level > _cups_debug_level)
535     return;
536
537   if (debug_filter)
538   {
539     int result;                         /* Filter result */
540
541     _cupsMutexLock(&debug_mutex);
542     result = regexec(debug_filter, s, 0, NULL, 0);
543     _cupsMutexUnlock(&debug_mutex);
544
545     if (result)
546       return;
547   }
548
549  /*
550   * Format the message...
551   */
552
553   gettimeofday(&curtime, NULL);
554   bytes = snprintf(buffer, sizeof(buffer), "%02d:%02d:%02d.%03d %s",
555                    (int)((curtime.tv_sec / 3600) % 24),
556                    (int)((curtime.tv_sec / 60) % 60),
557                    (int)(curtime.tv_sec % 60), (int)(curtime.tv_usec / 1000),
558                    s);
559
560   if (bytes >= (sizeof(buffer) - 1))
561   {
562     buffer[sizeof(buffer) - 2] = '\n';
563     bytes = sizeof(buffer) - 1;
564   }
565   else if (buffer[bytes - 1] != '\n')
566   {
567     buffer[bytes++] = '\n';
568     buffer[bytes]   = '\0';
569   }
570
571  /*
572   * Write it out...
573   */
574
575   write(_cups_debug_fd, buffer, bytes);
576 }
577
578
579 /*
580  * '_cups_debug_set()' - Enable or disable debug logging.
581  */
582
583 void DLLExport
584 _cups_debug_set(const char *logfile,    /* I - Log file or NULL */
585                 const char *level,      /* I - Log level or NULL */
586                 const char *filter,     /* I - Filter string or NULL */
587                 int        force)       /* I - Force initialization */
588 {
589   _cupsMutexLock(&debug_mutex);
590
591   if (!debug_init || force)
592   {
593    /*
594     * Restore debug settings to defaults...
595     */
596
597     if (_cups_debug_fd != -1)
598     {
599       close(_cups_debug_fd);
600       _cups_debug_fd = -1;
601     }
602
603     if (debug_filter)
604     {
605       regfree((regex_t *)debug_filter);
606       debug_filter = NULL;
607     }
608
609     _cups_debug_level = 1;
610
611    /*
612     * Open logs, set log levels, etc.
613     */
614
615     if (!logfile)
616       _cups_debug_fd = -1;
617     else if (!strcmp(logfile, "-"))
618       _cups_debug_fd = 2;
619     else
620     {
621       char      buffer[1024];           /* Filename buffer */
622
623       snprintf(buffer, sizeof(buffer), logfile, getpid());
624
625       if (buffer[0] == '+')
626         _cups_debug_fd = open(buffer + 1, O_WRONLY | O_APPEND | O_CREAT, 0644);
627       else
628         _cups_debug_fd = open(buffer, O_WRONLY | O_TRUNC | O_CREAT, 0644);
629     }
630
631     if (level)
632       _cups_debug_level = atoi(level);
633
634     if (filter)
635     {
636       if ((debug_filter = (regex_t *)calloc(1, sizeof(regex_t))) == NULL)
637         fputs("Unable to allocate memory for CUPS_DEBUG_FILTER - results not "
638               "filtered!\n", stderr);
639       else if (regcomp(debug_filter, filter, REG_EXTENDED))
640       {
641         fputs("Bad regular expression in CUPS_DEBUG_FILTER - results not "
642               "filtered!\n", stderr);
643         free(debug_filter);
644         debug_filter = NULL;
645       }
646     }
647
648     debug_init = 1;
649   }
650
651   _cupsMutexUnlock(&debug_mutex);
652 }
653 #endif /* DEBUG */
654
655
656 /*
657  * End of "$Id: debug.c 10234 2012-02-06 19:35:59Z mike $".
658  */