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