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