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