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