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